e2e: wait 5 mins for LB create by jackfrancis · Pull Request #2162 · kubernetes-sigs/cluster-api-provider-azure

jackfrancis · 2022-03-10T20:29:35Z

What type of PR is this?

/kind flake

What this PR does / why we need it:

Observed a flake waiting for LB create here:

https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/kubernetes-sigs_cluster-api-provider-azure/2160/pull-cluster-api-provider-azure-e2e/1501991622571724800/build-log.txt

This PR increases the timeout tolerance for the creation of a LoadBalancer to 5 mins from 30 seconds.

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #

Special notes for your reviewer:

Please confirm that if this PR changes any image versions, then that's the sole change this PR makes.

TODOs:

squashed commits
includes documentation
adds unit tests

Release note:

NONE

k8s-ci-robot · 2022-03-10T20:29:47Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by:
To complete the pull request process, please assign neolit123 after the PR has been reviewed.
You can assign the PR to them by writing /assign @neolit123 in a comment when ready.

The full list of commands accepted by this bot can be found here.

Details

Needs approval from an approver in each of these files:

OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

CecileRobertMichon · 2022-03-10T20:47:52Z

 			}
 			return nil
-		}, retryableOperationTimeout, retryableOperationSleepBetweenRetries).Should(Succeed())
+		}, waitForLBCreateTimeout, retryableOperationSleepBetweenRetries).Should(Succeed())


Looking at the logs Mar 10 19:25:52.827: INFO: waiting for service default/web-windowsarn1ku-elb to be available it looks like the flake is actually at the step above WaitForServiceAvailable https://github.com/kubernetes-sigs/cluster-api-provider-azure/pull/2162/files#diff-b1cadbd362567a300bb6df435abeafb8f91e45cfbca237a17b37253120d87aa5R143

�[91mFull Stack Trace�[0m sigs.k8s.io/cluster-api-provider-azure/test/e2e.WaitForServiceAvailable({0x25dc9c0, 0xc0000560d0}, {{0x259ebe0, 0xc000bb4e20}, 0xc000d84780, 0xc000bd6900}, {0xc00047e760, 0x2, 0x2}) /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/test/e2e/helpers.go:262 +0x49

You're right.

This is super confusing:

sigs.k8s.io/cluster-api-provider-azure/test/e2e.AzureLBSpec({0x25dc9c0, 0xc0000560d0}, 0x6) /home/prow/go/src/sigs.k8s.io/cluster-api-provider-azure/test/e2e/azure_lb.go:220 +0x15aa

L229 on the branch that produced this flake are in a different flow:

cluster-api-provider-azure/test/e2e/azure_lb.go

Line 220 in c2781f0

if err != nil {

In any event... it seems like we had a flake where the LB was not ready in 15 mins :(

was this after #2157 merged?

based on commit history of this branch, no

https://github.com/jackfrancis/cluster-api-provider-azure/commits/86f39f5de2ae6c6973cd0aae869503b640494313

Prow does rebase before it runs jobs and looks like it did include the change since it has "waiting for the ilb service to be deleted":

�[1mSTEP�[0m: waiting for service default/web-windowsarn1ku-ilb to be available Mar 10 19:24:09.332: INFO: waiting for service default/web-windowsarn1ku-ilb to be available Mar 10 19:25:20.174: INFO: service default/web-windowsarn1ku-ilb is available, took 1m10.842282999s �[1mSTEP�[0m: connecting to the internal LB service from a curl pod Mar 10 19:25:20.279: INFO: starting to create a curl to ilb job �[1mSTEP�[0m: waiting for job default/curl-to-ilb-jobx0ek1 to be complete Mar 10 19:25:20.389: INFO: waiting for job default/curl-to-ilb-jobx0ek1 to be complete Mar 10 19:25:30.598: INFO: job default/curl-to-ilb-jobx0ek1 is complete, took 10.209170132s �[1mSTEP�[0m: deleting the ilb test resources Mar 10 19:25:30.598: INFO: starting to delete the ilb service: web-windowsarn1ku-ilb Mar 10 19:25:30.745: INFO: waiting for the ilb service to be deleted: web-windowsarn1ku-ilb Mar 10 19:25:52.588: INFO: deleting the ilb job: curl-to-ilb-jobx0ek1 �[1mSTEP�[0m: creating an external Load Balancer service Mar 10 19:25:52.697: INFO: starting to create an external Load Balancer service �[1mSTEP�[0m: waiting for service default/web-windowsarn1ku-elb to be available Mar 10 19:25:52.827: INFO: waiting for service default/web-windowsarn1ku-elb to be available

I would look at cloud provider logs to try and figure out what happened

Looks like some sort of transient error happened:

E0310 19:40:56.433186 1 azure_backoff.go:332] InterfacesClient.CreateOrUpdate(capz-e2e-42b9n-nic) failed: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded E0310 19:40:56.433265 1 azure_loadbalancer.go:185] reconcileLoadBalancer(default/web-windowsarn1ku-elb) failed: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded I0310 19:40:56.433304 1 controller.go:848] Finished syncing service "default/web-windowsarn1ku-elb" (15m3.642610408s) E0310 19:40:56.433327 1 controller.go:310] error processing service default/web-windowsarn1ku-elb (will retry): failed to ensure load balancer: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded I0310 19:40:56.433911 1 event.go:291] "Event occurred" object="default/web-windowsarn1ku-elb" kind="Service" apiVersion="v1" type="Warning" reason="SyncLoadBalancerFailed" message="Error syncing load balancer: failed to ensure load balancer: Retriable: true, RetryAfter: 0s, HTTPStatusCode: -1, RawError: Future#WaitForCompletion: context has been cancelled: StatusCode=200 -- Original Error: context deadline exceeded"

and then it eventually succeeded:

I0310 19:41:07.302039 1 event.go:291] "Event occurred" object="default/web-windowsarn1ku-elb" kind="Service" apiVersion="v1" type="Normal" reason="EnsuredLoadBalancer" message="Ensured load balancer"

19:41 is over 15 minutes from 19:25 which explains the timeout.

https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/kubernetes-sigs_cluster-api-provider-azure/2160/pull-cluster-api-provider-azure-e2e/1501991622571724800/artifacts/clusters/capz-e2e-7ehh4v-ha/kube-system/kube-controller-manager-capz-e2e-7ehh4v-ha-control-plane-bk7q7/kube-controller-manager.log

I was just coming to the same conclusion

I0310 19:25:52.790705 1 controller.go:403] Ensuring load balancer for service default/web-windowsarn1ku-elb
...
I0310 19:41:07.440858 1 controller.go:848] Finished syncing service "default/web-windowsarn1ku-elb" (6.007310418s)

k8s-ci-robot · 2022-03-10T21:12:25Z

@jackfrancis: The following test failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
pull-cluster-api-provider-azure-ci-entrypoint	`86f39f5`	link	false	`/test pull-cluster-api-provider-azure-ci-entrypoint`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Details

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

e2e: wait 5 mins for LB create

86f39f5

k8s-ci-robot added do-not-merge/release-note-label-needed Indicates that a PR should not merge because it's missing one of the release note labels. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. labels Mar 10, 2022

k8s-ci-robot requested review from alexeldeib and jsturtevant March 10, 2022 20:29

CecileRobertMichon reviewed Mar 10, 2022

View reviewed changes

jackfrancis closed this Mar 10, 2022

jackfrancis deleted the e2e-lb-wait-for-create branch December 9, 2022 22:50

CecileRobertMichon mentioned this pull request Jan 30, 2023

Switch flavor and test templates to external cloud-provider #3105

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

e2e: wait 5 mins for LB create#2162

e2e: wait 5 mins for LB create#2162
jackfrancis wants to merge 1 commit into
kubernetes-sigs:mainfrom
jackfrancis:e2e-lb-wait-for-create

jackfrancis commented Mar 10, 2022 •

edited

Loading

Uh oh!

k8s-ci-robot commented Mar 10, 2022

Uh oh!

CecileRobertMichon Mar 10, 2022

Uh oh!

jackfrancis Mar 10, 2022

Uh oh!

CecileRobertMichon Mar 10, 2022

Uh oh!

jackfrancis Mar 10, 2022

Uh oh!

CecileRobertMichon Mar 10, 2022

Uh oh!

CecileRobertMichon Mar 10, 2022

Uh oh!

jackfrancis Mar 10, 2022

Uh oh!

k8s-ci-robot commented Mar 10, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

jackfrancis commented Mar 10, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

k8s-ci-robot commented Mar 10, 2022

Uh oh!

CecileRobertMichon Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

jackfrancis Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

CecileRobertMichon Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

jackfrancis Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

CecileRobertMichon Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

CecileRobertMichon Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

jackfrancis Mar 10, 2022

Choose a reason for hiding this comment

Uh oh!

k8s-ci-robot commented Mar 10, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

jackfrancis commented Mar 10, 2022 •

edited

Loading