Repository: knative/serving
Pull request #9325 (2020-09-07 22:42:29)

Fix intermittent 404 in TestServiceWithTrafficSplit
While debugging the linked issue, I noticed that the test was mistakenly thinking that the Service was Ready before the kingress had even been reprogrammed (let alone probed!).  When I drilled into why I discovered that it is possible for the Route controller, when it hits an error creating a placeholder service to trigger a status update that inadvertently reports the Route as Ready before it has even updated the kingress resource.

The sequence of events here is:
1. `PreProcessReconcile` changes `Ready: Unknown` in preparation for an `ObservedGeneration` bump.
2. The early traffic assignment computation returns the condition to `Ready: True`.
3. Before we even reach the `kingress` update, the placeholder service update errors out.
4. `PostProcessReconcile` bumps the `ObservedGeneration`.
5. `UpdateStatus` records the status.

The net effect of this is that we have put the `Route` into an `IsReady()` state before we've even attempted to reconcile the `kingress`, prompting the tests to probe and get a 404.

The fix is to `MarkIngressNotConfigured` upon observing new generations, since this is the last thing we'll flip back on our path to `Ready: True`, but I wonder whether `PreProcessReconcile` should take a callback to let (require?) the reconciler itself to specify how to properly adjust the conditions.

Fixes: https://github.com/knative-sandbox/net-contour/issues/238

/assign @tcnghia @vagababov 
cc @dprotaso @whaught 

```release-note
Fixes a race where the Route controller would report readiness prematurely.
```


knative-prow-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/knative/serving/pull/9325#" title="Author self-approved">mattmoor</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=knative%2Fserving).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[pkg/reconciler/route/OWNERS](https://github.com/knative/serving/blob/master/pkg/reconciler/route/OWNERS)~~ [mattmoor]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
knative-prow-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/knative/serving/pull/9325#" title="Author self-approved">mattmoor</a>*, *<a href="https://github.com/knative/serving/pull/9325#pullrequestreview-483721004" title="LGTM">tcnghia</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=knative%2Fserving).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[pkg/reconciler/route/OWNERS](https://github.com/knative/serving/blob/master/pkg/reconciler/route/OWNERS)~~ [mattmoor,tcnghia]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
knative-metrics-robot: The following is the coverage report on the affected files.
Say `/test pull-knative-serving-go-coverage` to re-run this coverage report

File | Old Coverage | New Coverage | Delta
---- |:------------:|:------------:|:-----:
[pkg/reconciler/route/route.go](https://storage.cloud.google.com/knative-prow/pr-logs/pull/knative_serving/9325/pull-knative-serving-go-coverage/1303101469494349832/artifacts/line-cov.html#file0) | 85.2% | 85.4% | 0.2

mattmoor: /test pull-knative-serving-contour-latest
knative-prow-robot: @mattmoor: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-serving-contour-latest | 0a888ff6bc2e3bbe481ba5f70c097c551939bd87 | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/9325/pull-knative-serving-contour-latest/1303106753520472064) | `/test pull-knative-serving-contour-latest`

[Full PR test history](https://gubernator.knative.dev/pr/knative_serving/9325). [Your PR dashboard](https://gubernator.knative.dev/pr/mattmoor).

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository. I understand the commands that are listed [here](https://go.k8s.io/bot-commands).
</details>
<!-- test report -->
mattmoor: /test pull-knative-serving-contour-latest

Noted the 503 here: https://github.com/knative-sandbox/net-contour/issues/214
tcnghia: /unhold

Patch:
diff --git a/pkg/reconciler/route/route.go b/pkg/reconciler/route/route.go
index d19a8113d..64995b5e8 100644
--- a/pkg/reconciler/route/route.go
+++ b/pkg/reconciler/route/route.go
@@ -108,6 +108,16 @@ func (c *Reconciler) ReconcileKind(ctx context.Context, r *v1.Route) pkgreconcil
 	logger := logging.FromContext(ctx)
 	logger.Debugf("Reconciling route: %#v", r.Spec)
 
+	// When a new generation is observed for the first time, we need to make sure that we
+	// do not report ourselves as being ready prematurely due to an error during
+	// reconciliation.  For instance, if we were to hit an error creating new placeholder
+	// service, we might report "Ready: True" with a bumped ObservedGeneration without
+	// having updated the kingress at all!
+	// We hit this in: https://github.com/knative-sandbox/net-contour/issues/238
+	if r.GetObjectMeta().GetGeneration() != r.Status.ObservedGeneration {
+		r.Status.MarkIngressNotConfigured()
+	}
+
 	// Configure traffic based on the RouteSpec.
 	traffic, err := c.configureTraffic(ctx, r)
 	if traffic == nil || err != nil {


Test patch:
diff --git a/pkg/reconciler/route/table_test.go b/pkg/reconciler/route/table_test.go
index da30ab23d..a82786533 100644
--- a/pkg/reconciler/route/table_test.go
+++ b/pkg/reconciler/route/table_test.go
@@ -82,7 +82,7 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "first-reconcile", WithConfigTarget("not-ready"), WithURL,
-				WithRouteGeneration(2009), WithRouteObservedGeneration,
+				WithRouteGeneration(2009), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				// The first reconciliation initializes the conditions and reflects
 				// that the referenced configuration is not yet ready.
 				WithInitRouteConditions, MarkConfigurationNotReady("not-ready")),
@@ -101,7 +101,7 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "first-reconcile", WithConfigTarget("permanently-failed"), WithURL,
-				WithRouteGeneration(2020), WithRouteObservedGeneration,
+				WithRouteGeneration(2020), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				WithInitRouteConditions, MarkConfigurationFailed("permanently-failed")),
 		}},
 		Key: "default/first-reconcile",
@@ -119,7 +119,7 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "first-reconcile", WithConfigTarget("not-ready"), WithURL,
-				WithRouteGeneration(42), WithRouteObservedGeneration,
+				WithRouteGeneration(42), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				WithInitRouteConditions, MarkConfigurationNotReady("not-ready")),
 		}},
 		WantEvents: []string{
@@ -387,8 +387,15 @@ func TestReconcile(t *testing.T) {
 			InduceFailure("create", "services"),
 		},
 		Objects: []runtime.Object{
-			Route("default", "create-svc-failure", WithConfigTarget("config"), WithRouteFinalizer,
-				WithRouteGeneration(2007)),
+			Route("default", "create-svc-failure",
+				WithConfigTarget("config"), WithRouteFinalizer,
+				WithRouteGeneration(2007), WithURL, WithAddress, WithInitRouteConditions,
+				MarkTrafficAssigned, WithStatusTraffic(
+					v1.TrafficTarget{
+						RevisionName:   "config-00001",
+						Percent:        ptr.Int64(100),
+						LatestRevision: ptr.Bool(true),
+					})),
 			cfg("default", "config",
 				WithConfigGeneration(1), WithLatestCreated("config-00001"), WithLatestReady("config-00001")),
 			rev("default", "config", 1, MarkRevisionReady, WithRevName("config-00001")),
@@ -397,18 +404,19 @@ func TestReconcile(t *testing.T) {
 			simplePlaceholderK8sService(getContext(), Route("default", "create-svc-failure", WithConfigTarget("config")), ""),
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
-			Object: Route("default", "create-svc-failure", WithConfigTarget("config"),
-				WithRouteFinalizer,
-				// Populated by reconciliation when we've failed to create
-				// the K8s service.
-				WithRouteGeneration(2007), WithRouteObservedGeneration,
-				WithURL, WithAddress, WithInitRouteConditions,
+			Object: Route("default", "create-svc-failure",
+				WithConfigTarget("config"), WithRouteFinalizer,
+				WithRouteGeneration(2007), WithURL, WithAddress, WithInitRouteConditions,
 				MarkTrafficAssigned, WithStatusTraffic(
 					v1.TrafficTarget{
 						RevisionName:   "config-00001",
 						Percent:        ptr.Int64(100),
 						LatestRevision: ptr.Bool(true),
-					})),
+					}),
+				// Despite the failure creating the placeholder service we see the
+				// Ready condition toggled to Unknown before the ObservedGeneration
+				// is bumped.
+				MarkIngressNotConfigured, WithRouteObservedGeneration),
 		}},
 		WantEvents: []string{
 			Eventf(corev1.EventTypeWarning, "CreationFailed", "Failed to create placeholder service %q: %v",
@@ -457,7 +465,8 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "ingress-create-failure", WithConfigTarget("config"),
-				WithRouteFinalizer, WithRouteGeneration(1), WithRouteObservedGeneration,
+				WithRouteFinalizer, WithRouteGeneration(1),
+				MarkIngressNotConfigured, WithRouteObservedGeneration,
 				// Populated by reconciliation when we fail to create the ingress.
 				WithURL, WithAddress, WithRouteConditionsAutoTLSDisabled,
 				MarkTrafficAssigned, WithStatusTraffic(
@@ -1218,7 +1227,7 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "config-missing", WithConfigTarget("not-found"), WithURL,
-				WithRouteGeneration(1), WithRouteObservedGeneration,
+				WithRouteGeneration(1), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				WithInitRouteConditions, MarkMissingTrafficTarget("Configuration", "not-found")),
 		}},
 		PostConditions: []func(*testing.T, *TableRow){
@@ -1235,7 +1244,7 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "missing-revision-direct", WithRevTarget("not-found"), WithURL,
-				WithRouteGeneration(1988), WithRouteObservedGeneration,
+				WithRouteGeneration(1988), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				WithInitRouteConditions, MarkMissingTrafficTarget("Revision", "not-found")),
 		}},
 		PostConditions: []func(*testing.T, *TableRow){
@@ -1252,7 +1261,7 @@ func TestReconcile(t *testing.T) {
 		},
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "missing-revision-indirect", WithConfigTarget("config"), WithURL,
-				WithRouteGeneration(2006), WithRouteObservedGeneration,
+				WithRouteGeneration(2006), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				WithInitRouteConditions, MarkMissingTrafficTarget("Revision", "config-00001")),
 		}},
 		Key: "default/missing-revision-indirect",
@@ -1651,8 +1660,8 @@ func TestReconcile(t *testing.T) {
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "split", WithURL, WithAddress,
 				WithInitRouteConditions, MarkTrafficAssigned, MarkIngressReady,
+				WithRouteGeneration(1), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				MarkConfigurationNotReady("green"),
-				WithRouteGeneration(1), WithRouteObservedGeneration,
 				WithSpecTraffic(
 					v1.TrafficTarget{
 						ConfigurationName: "blue",
@@ -2298,7 +2307,7 @@ func TestReconcileEnableAutoTLS(t *testing.T) {
 		WantStatusUpdates: []clientgotesting.UpdateActionImpl{{
 			Object: Route("default", "becomes-ready", WithConfigTarget("config"),
 				WithRouteUID("12-34"),
-				WithRouteGeneration(1), WithRouteObservedGeneration,
+				WithRouteGeneration(1), MarkIngressNotConfigured, WithRouteObservedGeneration,
 				WithAddress, WithInitRouteConditions, WithURL,
 				MarkTrafficAssigned, WithStatusTraffic(
 					v1.TrafficTarget{