Repository: knative/serving
Pull request #10311 (2020-12-08 17:11:43)

Fix the bug when the rollout was in a busy loop preventing ingress from being ready
The bug was introduced, thanks for @markusthoemmes for finding it, when
I added `stepRevisions` call.
That call would compute the next rollout step time and update the
corresponding field on the rollout.
Unfortunately this can happen before `ObserveReady` is called and the
rest of the rollout params are computed.
This lead to `step=0`, which meant we'd never progress and constantly
update the next step time, creating a busy loop of sorts.

The fix is to not step revisions until we have computed the rest of the
stats, basically by gating `stepSize > 0`, which is guaranteed to be at
least 1, when the readiness is observed.

Also added some logging to help with this rollout debugging.

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

This pull-request has been approved by: *<a href="https://github.com/knative/serving/pull/10311#" title="Author self-approved">vagababov</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)~~ [vagababov]

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":[]} -->
codecov[bot]: # [Codecov](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=h1) Report
> Merging [#10311](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=desc) (8ca9f23) into [master](https://codecov.io/gh/knative/serving/commit/afb967008effa639c3b6fb43394a5d5cca46d13f?el=desc) (afb9670) will **increase** coverage by `0.03%`.
> The diff coverage is `100.00%`.

[![Impacted file tree graph](https://codecov.io/gh/knative/serving/pull/10311/graphs/tree.svg?width=650&height=150&src=pr&token=MPpDfAj4Ui)](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master   #10311      +/-   ##
==========================================
+ Coverage   88.20%   88.23%   +0.03%     
==========================================
  Files         184      184              
  Lines        8654     8660       +6     
==========================================
+ Hits         7633     7641       +8     
+ Misses        786      784       -2     
  Partials      235      235              
```


| [Impacted Files](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [pkg/reconciler/route/reconcile\_resources.go](https://codecov.io/gh/knative/serving/pull/10311/diff?src=pr&el=tree#diff-cGtnL3JlY29uY2lsZXIvcm91dGUvcmVjb25jaWxlX3Jlc291cmNlcy5nbw==) | `87.15% <100.00%> (+0.74%)` | :arrow_up: |
| [pkg/reconciler/revision/reconcile\_resources.go](https://codecov.io/gh/knative/serving/pull/10311/diff?src=pr&el=tree#diff-cGtnL3JlY29uY2lsZXIvcmV2aXNpb24vcmVjb25jaWxlX3Jlc291cmNlcy5nbw==) | `80.72% <0.00%> (-2.41%)` | :arrow_down: |
| [pkg/activator/net/revision\_backends.go](https://codecov.io/gh/knative/serving/pull/10311/diff?src=pr&el=tree#diff-cGtnL2FjdGl2YXRvci9uZXQvcmV2aXNpb25fYmFja2VuZHMuZ28=) | `91.40% <0.00%> (+0.90%)` | :arrow_up: |
| [pkg/reconciler/configuration/configuration.go](https://codecov.io/gh/knative/serving/pull/10311/diff?src=pr&el=tree#diff-cGtnL3JlY29uY2lsZXIvY29uZmlndXJhdGlvbi9jb25maWd1cmF0aW9uLmdv) | `88.28% <0.00%> (+1.56%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=footer). Last update [afb9670...8ca9f23](https://codecov.io/gh/knative/serving/pull/10311?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).

knative-prow-robot: @vagababov: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-serving-upgrade-tests | 8ca9f237943415934a49019319271b9944878d7f | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/10311/pull-knative-serving-upgrade-tests/1336357830222942208) | `/test pull-knative-serving-upgrade-tests`

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

<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 -->
knative-prow-robot: @vagababov: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-serving-unit-tests | 05ff62f137ecca0cbb662118f71f9b2d5d6754a0 | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/10311/pull-knative-serving-unit-tests/1336395822249545728) | `/test pull-knative-serving-unit-tests`

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

<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 -->
knative-prow-robot: @vagababov: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-serving-upgrade-tests | 52f7023e01b489db8b4bb159de9019e2cdd95aa7 | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/10311/pull-knative-serving-upgrade-tests/1336404993174933504) | `/test pull-knative-serving-upgrade-tests`

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

<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 -->
vagababov: Succeeding when you want a fail
/test pull-knative-serving-upgrade-tests 
knative-prow-robot: @vagababov: The following test **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-serving-istio-stable-no-mesh | 722daa263497a33be9fd5ce9d6c2f544ae31f8e1 | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/10311/pull-knative-serving-istio-stable-no-mesh/1336426266592546816) | `/test pull-knative-serving-istio-stable-no-mesh`

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

<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 -->
vagababov: /test pull-knative-serving-upgrade-tests
vagababov: /test pull-knative-serving-istio-stable-no-mesh
vagababov: /assign @tcnghia 
vagababov: /unhold
knative-prow-robot: @vagababov: The following tests **failed**, say `/retest` to rerun all failed tests:

Test name | Commit | Details | Rerun command
--- | --- | --- | ---
pull-knative-serving-istio-stable-no-mesh | 722daa263497a33be9fd5ce9d6c2f544ae31f8e1 | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/10311/pull-knative-serving-istio-stable-no-mesh/1336426266592546816) | `/test pull-knative-serving-istio-stable-no-mesh`
pull-knative-serving-upgrade-tests | 29c743ac5575708e27c5888cc94454a5155246db | [link](https://prow.knative.dev/view/gs/knative-prow/pr-logs/pull/knative_serving/10311/pull-knative-serving-upgrade-tests/1336450698325266432) | `/test pull-knative-serving-upgrade-tests`

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

<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 -->
vagababov: 😓 
unrelated 
/retest

Patch:
diff --git a/pkg/reconciler/route/reconcile_resources.go b/pkg/reconciler/route/reconcile_resources.go
index 14a91c791..e84c373b5 100644
--- a/pkg/reconciler/route/reconcile_resources.go
+++ b/pkg/reconciler/route/reconcile_resources.go
@@ -21,7 +21,9 @@ import (
 	"encoding/json"
 	"fmt"
 
+	"github.com/google/go-cmp/cmp"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"golang.org/x/sync/errgroup"
 	corev1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/api/equality"
@@ -77,9 +79,19 @@ func (c *Reconciler) reconcileIngress(
 		// And recompute the rollout state.
 		effectiveRO := curRO.Step(prevRO, int(c.clock.Now().UnixNano()))
 
+		// Comparing and diffing isn't cheap so do it only if we're going
+		// to actually log the message.
+		// Those are well known types, cmp won't panic.
+		logger := logging.FromContext(ctx).Desugar()
+		if logger.Core().Enabled(zapcore.DebugLevel) && !cmp.Equal(prevRO, effectiveRO) {
+			logger.Debug("Rollout diff:(-was,+now)",
+				zap.String("diff", cmp.Diff(prevRO, effectiveRO)))
+		}
+
 		// Now check if the ingress status changed from not ready to ready.
 		rtView := r.Status.GetCondition(v1.RouteConditionIngressReady)
 		if ingress.IsReady() && !rtView.IsTrue() {
+			logger.Debug("Observing Ingress not-ready to ready switch condition for rollout")
 			effectiveRO.ObserveReady(int(c.clock.Now().UnixNano()))
 		}
 
@@ -92,13 +104,14 @@ func (c *Reconciler) reconcileIngress(
 		if !equality.Semantic.DeepEqual(ingress.Spec, desired.Spec) ||
 			!equality.Semantic.DeepEqual(ingress.Annotations, desired.Annotations) ||
 			!equality.Semantic.DeepEqual(ingress.Labels, desired.Labels) {
+
 			// It is notable that one reason for differences here may be defaulting.
 			// When that is the case, the Update will end up being a nop because the
 			// webhook will bring them into alignment and no new reconciliation will occur.
 			// Also, compare annotation and label in case ingress.Class or parent route's labels
 			// is updated.
 
-			// Don't modify the informers copy
+			// Don't modify the informers copy.
 			origin := ingress.DeepCopy()
 			origin.Spec = desired.Spec
 			origin.Annotations = desired.Annotations
diff --git a/pkg/reconciler/route/traffic/rollout.go b/pkg/reconciler/route/traffic/rollout.go
index fc587484f..c9ac44c38 100644
--- a/pkg/reconciler/route/traffic/rollout.go
+++ b/pkg/reconciler/route/traffic/rollout.go
@@ -196,7 +196,7 @@ func (cur *Rollout) Step(prev *Rollout, nowTS int) *Rollout {
 				j++
 			case ccfgs[i].ConfigurationName < pcfgs[j].ConfigurationName:
 				// A new config, has been added. No action for rollout though.
-				// Keep it if it will receive traffic.
+				// Keep it for future rollout actions.
 				if ccfgs[i].Percent != 0 {
 					ret = append(ret, *ccfgs[i])
 				}
@@ -323,27 +323,37 @@ func stepConfig(goal, prev *ConfigurationRollout, nowTS int) *ConfigurationRollo
 	// If it matches the last revision of the previous rollout state (or there were no revisions)
 	// then no new rollout has begun for this configuration.
 	if len(prev.Revisions) == 0 || goal.Revisions[0].RevisionName == prev.Revisions[pc-1].RevisionName {
-		if len(prev.Revisions) > 0 {
+		// So if |prev.revisions| == 0 => then there was no rollout —
+		// nothing is required to step.
+		// If |prev.revisions| == 1 and it matches current revision then
+		// we're done.
+		// Thus we need to perform work only if there is more than one
+		// revision in the previous state.
+		if len(prev.Revisions) > 1 {
 			ret.Revisions = prev.Revisions
 
-			// TODO(vagababov): here would go the logic to compute new percentages for the rollout,
-			// i.e step function, so return value will change, depending on that.
-			// Copy the duration info from the previous when no new revision
+			// Copy various rollout stats from the previous when no new revision
 			// has been created.
+			ret.StartTime = prev.StartTime
 			ret.Deadline = prev.Deadline
 			ret.NextStepTime = prev.NextStepTime
 			ret.StepDuration = prev.StepDuration
-			ret.StartTime = prev.StartTime
 			ret.StepSize = prev.StepSize
-			// adjustPercentage above would've already accounted if target for the
-			// whole Configuration changed up or down. So here we should just redistribute
-			// the existing values.
-			stepRevisions(ret, nowTS)
+			// We might end up here before `ObserveReady` is called.
+			// In that case don't step individual revisions just yet.
+			if ret.StepSize > 0 {
+				// adjustPercentage above would've already accounted if target for the
+				// whole Configuration changed up or down. So here we should just redistribute
+				// the existing values.
+				stepRevisions(ret, nowTS)
+			}
 		}
 		return ret
 	}
 
-	// Otherwise we start a rollout, which means we need to stamp the starttime.
+	// Otherwise we start a rollout, which means we need to stamp the starttime,
+	// the rest of the fields will remain unset and `ObserveReady` will
+	// compute them when the ingress becomes ready.
 	ret.StartTime = nowTS
 
 	// Go backwards and find first revision with traffic assignment > 0.


Test patch:
diff --git a/pkg/reconciler/route/traffic/rollout_test.go b/pkg/reconciler/route/traffic/rollout_test.go
index a5124af1c..8927d5143 100644
--- a/pkg/reconciler/route/traffic/rollout_test.go
+++ b/pkg/reconciler/route/traffic/rollout_test.go
@@ -31,7 +31,7 @@ import (
 )
 
 func TestStep(t *testing.T) {
-	now := int(time.Now().UnixNano())
+	const now = 2020
 	tests := []struct {
 		name            string
 		prev, cur, want *Rollout
@@ -78,7 +78,7 @@ func TestStep(t *testing.T) {
 					RevisionName: "let-it-bleed",
 					Percent:      100,
 				}},
-				Deadline:     2006, // <- Those should be ignored.
+				Deadline:     2006, // <- Those should be kept.
 				NextStepTime: 2009,
 				StepDuration: 2020,
 				StartTime:    2004,
@@ -93,11 +93,6 @@ func TestStep(t *testing.T) {
 					RevisionName: "let-it-bleed",
 					Percent:      100,
 				}},
-				Deadline:     1982, // <- Those should be copied.
-				NextStepTime: 1984,
-				StepDuration: 1988,
-				StartTime:    1955,
-				StepSize:     15,
 			}},
 		},
 		want: &Rollout{
@@ -108,11 +103,107 @@ func TestStep(t *testing.T) {
 					RevisionName: "let-it-bleed",
 					Percent:      100,
 				}},
-				Deadline:     1982,
-				NextStepTime: 1984,
-				StepDuration: 1988,
-				StartTime:    1955,
-				StepSize:     15,
+			}},
+		},
+	}, {
+		name: "simplest, step",
+		cur: &Rollout{
+			Configurations: []ConfigurationRollout{{
+				ConfigurationName: "mick",
+				Percent:           100,
+				Revisions: []RevisionRollout{{
+					RevisionName: "let-it-bleed",
+					Percent:      100,
+				}},
+				NextStepTime: 2009,
+				StepDuration: 2020,
+				StartTime:    2004,
+				StepSize:     14,
+			}},
+		},
+		prev: &Rollout{
+			Configurations: []ConfigurationRollout{{
+				ConfigurationName: "mick",
+				Percent:           100,
+				NextStepTime:      2019,
+				StepDuration:      5,
+				StartTime:         2004,
+				StepSize:          3,
+				Revisions: []RevisionRollout{{
+					RevisionName: "their-satanic-majesties-request",
+					Percent:      95,
+				}, {
+					RevisionName: "let-it-bleed",
+					Percent:      5,
+				}},
+			}},
+		},
+		want: &Rollout{
+			Configurations: []ConfigurationRollout{{
+				ConfigurationName: "mick",
+				Percent:           100,
+				Revisions: []RevisionRollout{{
+					RevisionName: "their-satanic-majesties-request",
+					Percent:      92, // -3
+				}, {
+					RevisionName: "let-it-bleed",
+					Percent:      8, // +3
+				}},
+				NextStepTime: 2020 + 5, // now + duration.
+				StepDuration: 5,
+				StartTime:    2004,
+				StepSize:     3,
+			}},
+		},
+	}, {
+		name: "simplest, step, when stepsize=0",
+		cur: &Rollout{
+			Configurations: []ConfigurationRollout{{
+				ConfigurationName: "mick",
+				Percent:           100,
+				Revisions: []RevisionRollout{{
+					RevisionName: "let-it-bleed",
+					Percent:      100,
+				}},
+				Deadline:     2006,
+				NextStepTime: 2009,
+				StepDuration: 2020,
+				StartTime:    2004,
+				StepSize:     14,
+			}},
+		},
+		prev: &Rollout{
+			Configurations: []ConfigurationRollout{{
+				ConfigurationName: "mick",
+				Percent:           100,
+				NextStepTime:      2019, // <- Those should be reset and/or updated.
+				StartTime:         2004,
+				StepDuration:      5,
+				StepSize:          0,
+				Revisions: []RevisionRollout{{
+					RevisionName: "their-satanic-majesties-request",
+					Percent:      95,
+				}, {
+					RevisionName: "let-it-bleed",
+					Percent:      5,
+				}},
+			}},
+		},
+		want: &Rollout{
+			Configurations: []ConfigurationRollout{{
+				ConfigurationName: "mick",
+				Percent:           100,
+				Revisions: []RevisionRollout{{
+					RevisionName: "their-satanic-majesties-request",
+					Percent:      95,
+				}, {
+					RevisionName: "let-it-bleed",
+					Percent:      5,
+				}},
+				NextStepTime: 2019,
+				StartTime:    2004,
+				StepDuration: 5,
+				StepSize:     0,
 			}},
 		},
 	}, {
@@ -200,6 +291,7 @@ func TestStep(t *testing.T) {
 				Deadline:     1982, // <- Those should be thrown out.
 				NextStepTime: 1984,
 				StepDuration: 1988,
+				StepSize:     11,
 			}},
 		},
 		want: &Rollout{