e2e test failed

[daisy-ycguo]

Affected PRs: #495 #484, which needs retest after fixing this.
Logs from e2e test:

=== RUN   TestTrafficSplit/replace_latest_tag_of_a_revision_with_old_and_give_latest_to_another_revision
Running 'kn service create echo12 --image gcr.io/knative-samples/helloworld-go -n kne2etests2'...
Running 'kn service describe echo12 -o jsonpath={.status.latestCreatedRevisionName} -n kne2etests2'...
Running 'kn service update echo12 --env TARGET=v2 -n kne2etests2'...
Running 'kn service describe echo12 -o jsonpath={.status.latestCreatedRevisionName} -n kne2etests2'...
Running 'kn service update echo12 --tag echo12-cpjww-1=latest -n kne2etests2'...
Running 'kn service update echo12 --untag latest --tag echo12-cpjww-1=old,echo12-mstfw-2=latest -n kne2etests2'...
Running 'kn service describe echo12 -o jsonpath={range .status.traffic[*]}{.tag}{','}{.revisionName}{','}{.percent}{','}{.latestRevision}{'|'}{end} -n kne2etests2'...
Running 'kn service delete echo12 -n kne2etests2'...
Running 'kubectl delete namespace kne2etests2'...
--- FAIL: TestTrafficSplit (338.92s)
    --- PASS: TestTrafficSplit/tag_two_revisions_as_v1_and_v2_and_give_50-50%_share (39.34s)
    --- PASS: TestTrafficSplit/ramp/up_down_a_revision_to_20%_adjusting_other_traffic_to_accommodate (14.25s)
    --- FAIL: TestTrafficSplit/tag_a_revision_as_candidate,_without_otherwise_changing_any_traffic_split (7.74s)
        traffic_split_test.go:368: assertion failed: 
            --- expectedTargets
            +++ formattedActualTargets
              []e2e.TargetFields{
              	{
              		Tag:      "",
            - 		Revision: "echo2-ytdyn-2",
            + 		Revision: "echo2-qjxkx-1",
              		Percent:  100,
              		Latest:   true,
              	},
              	{Tag: "candidate", Revision: "echo2-qjxkx-1"},
              }
            
    --- FAIL: TestTrafficSplit/tag_a_revision_as_candidate,_set_2%_traffic_adjusting_other_traffic_to_accommodate (7.12s)
        traffic_split_test.go:368: assertion failed: 
            --- expectedTargets
            +++ formattedActualTargets
              []e2e.TargetFields{
              	{
              		Tag:      "",
            - 		Revision: "echo3-rxqpk-2",
            + 		Revision: "echo3-yvncn-1",
              		Percent:  98,
              		Latest:   true,
              	},
              	{Tag: "candidate", Revision: "echo3-yvncn-1", Percent: 2},
              }
            
    --- PASS: TestTrafficSplit/update_tag_for_a_revision_from_candidate_to_current,_tag_current_is_present_on_another_revision (16.57s)
    --- PASS: TestTrafficSplit/update_tag_from_testing_to_staging_for_@latest_revision (8.58s)
    --- PASS: TestTrafficSplit/update_tag_from_testing_to_staging_for_a_revision_(non_@latest) (9.47s)
    --- PASS: TestTrafficSplit/remove_a_revision_with_tag_old_from_traffic_block_entirely (10.26s)
    --- PASS: TestTrafficSplit/tag_a_revision_as_stable_and_current_with_50-50%_traffic (7.37s)
    --- FAIL: TestTrafficSplit/revert_all_traffic_to_latest_ready_revision_of_service (6.42s)
        traffic_split_test.go:368: assertion failed: 
            --- expectedTargets
            +++ formattedActualTargets
              []e2e.TargetFields{
              	{
              		Tag:      "",
            - 		Revision: "echo9-jjnkt-2",
            + 		Revision: "echo9-wymdj-1",
              		Percent:  100,
              		Latest:   true,
              	},
              }
            
    --- PASS: TestTrafficSplit/tag_latest_ready_revision_of_service_as_current (6.66s)
    --- PASS: TestTrafficSplit/update_tag_for_a_revision_as_testing_and_assign_all_the_traffic_to_it: (10.60s)
    --- PASS: TestTrafficSplit/replace_latest_tag_of_a_revision_with_old_and_give_latest_to_another_revision (9.97s)
FAIL
FAIL	knative.dev/client/test/e2e	338.954s
Finished run, return code is 1
XML report written to /logs/artifacts/junit_BCtKZlsF.xml

[navidshaikh]

Adding notes here looking at the two referenced PR logs
For #495 logs:

Failed to successfully execute 'kn service create hello --image gcr.io/knative-samples/helloworld-go -n kne2etests1': Execution error: stderr: 'RevisionMissing: Revision "hello-lgpvy-1" referenced in traffic not found.

That's failure to create the service.

For #484 logs:
All the failures are mismatch for expected vs actual revision names for latestRevisionTrue target in traffic block.

Also all these tests are failing only for nightly release of serving.

[rhuss]

For the #495 logs, I'm not sure why the kn service create handling fails.

For the #484 logs, I'm pretty sure that this is related to knative/serving#5319 and maybe the way how BYO revision names are handled in
https://github.com/knative/serving/pull/5319/files#diff-ffae6f88426f91ba5373a40f4ea8bbb9R254-R260

Not sure if we are checking something wrong (and is fixed now in latest), or whether the upstream change is broken.

[navidshaikh]

/assign

[navidshaikh]

I think it's a timing issue. Although the service update is synchronous and kn returned when the config change is reconciled we see difference in revision-name for latestRevision:true target of service status right after the update and after few more seconds:

See below:

✗ kn service create svc --image gcr.io/knative-samples/helloworld-go --revision-name svc-rev-1; \
> kn service update svc --env TARGET=v2 --revision-name svc-rev-2;\
> kn service update svc --tag svc-rev-1=candidate --traffic candidate=2 --traffic @latest=98;\
> kn service describe svc -o yaml
Creating service 'svc' in namespace 'default':

  0.031s The Route is still working to reflect the latest desired specification.
  0.109s Configuration "svc" is waiting for a Revision to become ready.
  4.843s ...
  4.911s Ingress has not yet been reconciled.
  5.097s Ready to serve.

Service 'svc' created with latest revision 'svc-rev-1' and URL:
http://svc.default.example.com
Updating Service 'svc' in namespace 'default':

  0.027s Ready to serve.

Service 'svc' updated with latest revision 'svc-rev-1' (unchanged) and URL:
http://svc.default.example.com
Updating Service 'svc' in namespace 'default':

  0.022s The Route is still working to reflect the latest desired specification.
  0.100s Ingress has not yet been reconciled.
  0.607s Ready to serve.

Service 'svc' updated with latest revision 'svc-rev-1' (unchanged) and URL:
http://svc.default.example.com
apiVersion: serving.knative.dev/v1alpha1
kind: Service
metadata:
  annotations:
    serving.knative.dev/creator: minikube-user
    serving.knative.dev/lastModifier: minikube-user
  creationTimestamp: "2019-11-15T13:01:26Z"
  generation: 3
  name: svc
  namespace: default
  resourceVersion: "13133"
  selfLink: /apis/serving.knative.dev/v1alpha1/namespaces/default/services/svc
  uid: 085d8a6c-07a8-11ea-ad7d-4cb0ed8c7288
spec:
  template:
    metadata:
      annotations:
        client.knative.dev/user-image: gcr.io/knative-samples/helloworld-go
      creationTimestamp: null
      name: svc-rev-2
    spec:
      containerConcurrency: 0
      containers:
      - env:
        - name: TARGET
          value: v2
        image: gcr.io/knative-samples/helloworld-go@sha256:5ea96ba4b872685ff4ddb5cd8d1a97ec18c18fae79ee8df0d29f446c5efe5f50
        name: user-container
        readinessProbe:
          successThreshold: 1
          tcpSocket:
            port: 0
        resources: {}
      timeoutSeconds: 300
  traffic:
  - latestRevision: true
    percent: 98
  - latestRevision: false
    percent: 2
    revisionName: svc-rev-1
    tag: candidate
status:
  address:
    url: http://svc.default.svc.cluster.local
  conditions:
  - lastTransitionTime: "2019-11-15T13:01:31Z"
    status: "True"
    type: ConfigurationsReady
  - lastTransitionTime: "2019-11-15T13:01:32Z"
    status: "True"
    type: Ready
  - lastTransitionTime: "2019-11-15T13:01:32Z"
    status: "True"
    type: RoutesReady
  latestCreatedRevisionName: svc-rev-2
  latestReadyRevisionName: svc-rev-1
  observedGeneration: 3
  traffic:
  - latestRevision: true
    percent: 98
    revisionName: svc-rev-1
  - latestRevision: false
    percent: 2
    revisionName: svc-rev-1
    tag: candidate
    url: http://candidate-svc.default.example.com
  url: http://svc.default.example.com

Here ^^ .status.traffic[?(@.latestRevision==true)].revisionName is revisionName: svc-rev-1

Now, get the status again after few seconds:

 ✗ kn service describe svc -o yaml                                                                
apiVersion: serving.knative.dev/v1alpha1
kind: Service
metadata:
  annotations:
    serving.knative.dev/creator: minikube-user
    serving.knative.dev/lastModifier: minikube-user
  creationTimestamp: "2019-11-15T13:01:26Z"
  generation: 3
  name: svc
  namespace: default
  resourceVersion: "13191"
  selfLink: /apis/serving.knative.dev/v1alpha1/namespaces/default/services/svc
  uid: 085d8a6c-07a8-11ea-ad7d-4cb0ed8c7288
spec:
  template:
    metadata:
      annotations:
        client.knative.dev/user-image: gcr.io/knative-samples/helloworld-go
      creationTimestamp: null
      name: svc-rev-2
    spec:
      containerConcurrency: 0
      containers:
      - env:
        - name: TARGET
          value: v2
        image: gcr.io/knative-samples/helloworld-go@sha256:5ea96ba4b872685ff4ddb5cd8d1a97ec18c18fae79ee8df0d29f446c5efe5f50
        name: user-container
        readinessProbe:
          successThreshold: 1
          tcpSocket:
            port: 0
        resources: {}
      timeoutSeconds: 300
  traffic:
  - latestRevision: true
    percent: 98
  - latestRevision: false
    percent: 2
    revisionName: svc-rev-1
    tag: candidate
status:
  address:
    url: http://svc.default.svc.cluster.local
  conditions:
  - lastTransitionTime: "2019-11-15T13:01:31Z"
    status: "True"
    type: ConfigurationsReady
  - lastTransitionTime: "2019-11-15T13:01:35Z"
    status: "True"
    type: Ready
  - lastTransitionTime: "2019-11-15T13:01:35Z"
    status: "True"
    type: RoutesReady
  latestCreatedRevisionName: svc-rev-2
  latestReadyRevisionName: svc-rev-2
  observedGeneration: 3
  traffic:
  - latestRevision: true
    percent: 98
    revisionName: svc-rev-2
  - latestRevision: false
    percent: 2
    revisionName: svc-rev-1
    tag: candidate
    url: http://candidate-svc.default.example.com
  url: http://svc.default.example.com

Here ^^ .status.traffic[?(@.latestRevision==true)].revisionName is revisionName: svc-rev-2

We can add a couple of seconds delay when we verify the expected vs actual targets to work around this in kn e2e. However, the service update returned only after the service conditions returned true and thereafter the revision name's value in target latestReadyRevision: true got updated.

/cc @taragu @mattmoor We started seeing this in the nightly build since ~3 days, the related PR got into the serving master is knative/serving#5319. FYI this worked fine against serving v0.10.0.

[navidshaikh]

Reopening. time.Sleep workaround isn't reliable, seeing more of this ref: logs

    --- FAIL: TestTrafficSplit/tag_a_revision_as_candidate,_without_otherwise_changing_any_traffic_split (12.40s)
        traffic_split_test.go:376: assertion failed: 
            --- expectedTargets
            +++ formattedActualTargets
              []e2e.TargetFields{
              	{
              		Tag:      "",
            - 		Revision: "echo2-rev-2",
            + 		Revision: "echo2-rev-1",
              		Percent:  100,
              		Latest:   true,
              	},
              	{Tag: "candidate", Revision: "echo2-rev-1"},
              }