search

kubernetes-sigs / cluster-api

Home for Cluster API, a subproject of sig-cluster-lifecycle
https://cluster-api.sigs.k8s.io
Apache License 2.0
3.59k stars 1.32k forks source link

flakes in clusterctl upgrade tests #11133

Open cahillsf opened 2 months ago

cahillsf commented 2 months ago

summarized by @chrischdi 🙇

According to aggregated failures of the last two weeks, we still have some flakyness on our clusterctl upgrade tests.

Link to check if messages changed or we have new flakes on clusterctl upgrade tests: here

/kind flake

tormath1 commented 2 months ago

I'll have a look to the "Failed to create kind cluster" issue as I already noticed something similar on my own Kind setup and I think it's not isolated: https://github.com/kubernetes-sigs/kind/issues/3554 - I guess it's something to fix upstream.

EDIT: It seems to be an issue with inodes:

$ kind create cluster --retain --name=cluster3
Creating cluster "cluster3" ...
 ✓ Ensuring node image (kindest/node:v1.31.0) 🖼
 ✗ Preparing nodes 📦
ERROR: failed to create cluster: could not find a log line that matches "Reached target .*Multi-User System.*|detected cgroup v1"
$ podman logs -f 7eb0838e6bb2
...
Detected virtualization podman.
Detected architecture x86-64.

Welcome to Debian GNU/Linux 12 (bookworm)!

Failed to create control group inotify object: Too many open files
Failed to allocate manager object: Too many open files
[!!!!!!] Failed to allocate manager object.
Exiting PID 1...
chrischdi commented 2 months ago 
Failed to create control group inotify object: Too many open files
Failed to allocate manager object: Too many open files

That sounds very suspicious regarding to https://main.cluster-api.sigs.k8s.io/user/troubleshooting.html?highlight=sysctl#cluster-api-with-docker----too-many-open-files

Maybe would be a good start here to collect data about the actual used values :-)

BenTheElder commented 2 months ago

"cluster": "eks-prow-build-cluster",

I don't know if we're running https://github.com/kubernetes/k8s.io/blob/3f2c06a3c547765e21dce65d0adcb1144a93b518/infra/aws/terraform/prow-build-cluster/resources/kube-system/tune-sysctls_daemonset.yaml#L4 there or not

Also perhaps something else on the cluster is using a lot of them.

ameukam commented 2 months ago

I confirm the daemonset runs on the EKS cluster.

tormath1 commented 2 months ago

Thanks folks for confirming that the daemon set is correctly setting the sysctl parameters - so the error might be elsewhere, I noticed something else while reading the logs^1 of a failing test:

$ cat journal.log | grep -i "Journal started"
Aug 30 06:35:27 clusterctl-upgrade-management-fba3o1-control-plane systemd-journald[95]: Journal started
$ cat journal.log | grep -i "multi-user"
Aug 30 06:35:51 clusterctl-upgrade-management-fba3o1-control-plane systemd[1]: Reached target multi-user.target - Multi-User System.

While on a non failing setup:

root@kind-control-plane:/# journalctl | grep -i "multi-user"
Sep 05 12:16:31 kind-control-plane systemd[1]: Reached target multi-user.target - Multi-User System.
root@kind-control-plane:/# journalctl | grep -i "Journal started"
Sep 05 12:16:31 kind-control-plane systemd-journald[98]: Journal started

We can see that the multi-user.target^2 is reached at the same time as the journal started to log. On a failing test, there is a already 24 seconds of difference. I'm wondering if randomly (under heavy load) we don't reach the 30 seconds of timeout^3 for reaching the multi-user.target hence the failure.

BenTheElder commented 2 months ago

It's possible? This part shouldn't really take long though ..

I suspect that would be a noisy neighbor problem on the EKS cluster (I/O?)

Doesn't explain the inotify-exhaustion like failures.

sbueringer commented 2 months ago

We recently increased concurrency in our tests. With that we were able to reduce Job durations from 2h to 1h.

We thought it's a nice way to save us time and the community money.

Maybe we have to roll that back

tormath1 commented 2 months ago

We recently increased concurrency in our tests. With that we were able to reduce Job durations from 2h to 1h.

We thought it's a nice way to save us time and the community money.

Maybe we have to roll that back

Do you remember when this change has been applied ? Those Kind failures seem to start by the end of August.

sbueringer commented 2 months ago

main: https://github.com/kubernetes-sigs/cluster-api/pull/11067 release-1.8: https://github.com/kubernetes-sigs/cluster-api/pull/11144

cahillsf commented 2 months ago

related note ( i split off one of the messages into a separate issue https://github.com/kubernetes-sigs/cluster-api/issues/11209 just so this conversation didn't get too convoluted) -- we are going to try reverting the concurrency increase and see if the situation improves

https://github.com/kubernetes-sigs/cluster-api/pull/11220 https://github.com/kubernetes-sigs/cluster-api/pull/11222

BenTheElder commented 2 months ago

We can see that the multi-user.target2 is reached at the same time as the journal started to log. On a failing test, there is a already 24 seconds of difference. I'm wondering if randomly (under heavy load) we don't reach the 30 seconds of timeout3 for reaching the multi-user.target hence the failure.

That makes sense, ordinarily this part shouldn't take long, it doesn't need to fetch anything over the network and it should be pretty fast.

But in a resource starved environment it might take to long. In that environment I would also expect Kubernetes to be unstable though, api-server/etcd will be timing out if we make it that far.

cahillsf commented 1 month ago

carrying over some updates from the split off issue -- we have seen great improvements in the flakiness of the e2e tests after reverting the concurrency increase:

the updated plan/guidance for the rest of this release cycle re these e2e flakes is here: https://github.com/kubernetes-sigs/cluster-api/issues/11209#issuecomment-2379465352

sbueringer commented 1 month ago

@cahillsf What is the current state?

cahillsf commented 1 month ago

@cahillsf What is the current state?

sorry @sbueringer was out on PTO, i just updated the description with the current status (one net new flake pattern)

i did some investigation on the most frequent:

3 Failures: Internal error occurred: failed calling webhook [...] connect: connection refused

i was not able to find much indication in the logs about what might be going wrong here. could be some issue with the kube components but it seems we are not collecting these in the artifacts for this test. any thoughts as to how to better troubleshoot this? maybe ill open a PR to try to collect the kube-system logs for this test?

sbueringer commented 1 month ago

@cahillsf No worries, welcome back :)

failing example where the ClusterClass is not getting reconciled

Not sure if you meant it that way, but I think the problem is not that CC is not getting reconciled. The problem is that we cannot deploy the DockerClusterTemplate:

Internal error occurred: failed calling webhook "default.dockerclustertemplate.infrastructure.cluster.x-k8s.io": https://prow.k8s.io/view/gs/kubernetes-jenkins/logs/periodic-cluster-api-e2e-main/1839604474990039040

The consequence of that is then that the ClusterClass cannot be reconciled.

The question is, why is the CAPD webhook not up at this time.

Can we do a quick PR to drop this in docker.yaml?

    - old: "--leader-elect"
      new: "--leader-elect\n        - --logging-format=json"

Using JSON logging for e2e tests was a nice idea at the time, but overall it just makes troubleshooting without Loki/Grafana (which is what we do most of the time) pretty painful.

cahillsf commented 1 month ago

yes thanks for clarifying

Can we do a quick PR to drop this in docker.yaml?

Sure thing, ill add this replacement for all of the v1.8 providers -- sound good?

sbueringer commented 1 month ago

I would drop them entirely from docker.yaml

cahillsf commented 1 month ago

oh oh i misread on the first pass (see you've already approved but dropping the PR here so it gets linked: https://github.com/kubernetes-sigs/cluster-api/pull/11318)

sbueringer commented 1 month ago

Okay so what I was looking for was basically a way to correlate when the test failed and when CAPD was coming up. To then try to figure out what's going on. This should be easier with "regular" timestamps now.

In general I would have assumed:

cahillsf commented 1 month ago
  • that clusterctl waits until providers are up (maybe worth to check)

it does appear to, the management cluster is created with InitManagementClusterAndWatchControllerLogs which waits for all deployments to be available here by calling WaitForDeploymentsAvailable

the logic seems pretty straightforward and sound here? not sure if anything sticks out to you

  • that the kubectl apply has some sort of retry so it doesn't fail immediately (also worth to check)

it does not, CreateOrUpdate is called on the managementClusterProxy which is defined here and has no retry logic

can open a PR to add support for some retry option to be passed into CreateOrUpdate and see if that helps

sbueringer commented 1 month ago

the logic seems pretty straightforward and sound here? not sure if anything sticks out to you

Probably fine. I assume waiting for Available to be true on a Deployment means that the capi-controller Pod is Ready? (which would include readinessProbes to work which includes webhook server to be up)

It does not, CreateOrUpdate is called on the managementClusterProxy which is defined here and has no retry logic can open a PR to add support for some retry option to be passed into CreateOrUpdate and see if that helps

Ah okay, I thought we might have a retry. But it's probably a good thing. Adding a retry there might hide some problems

I see potentially a gap between Deployment being Available / Pod being Ready and kube-proxy updating iptables so the webhook is actually reachable.

I think it would be important to clarify the timeline:

Let's try to get those timestamps.

If there is only a gap of 1-2 seconds we might want to retry CreateOrUpdate with dry-run until all webhooks work and then run CreateOrUpdate once without dry-run.

cahillsf commented 1 month ago

I think it would be important to clarify the timeline:

  • based on Pod timestamps, when is the webhook server actually up (to confirm clusterctl is waiting correctly)
  • when is the request failing Let's try to get those timestamps.

If there is only a gap of 1-2 seconds we might want to retry CreateOrUpdate with dry-run until all webhooks work and then run CreateOrUpdate once without dry-run.

taking this same failure example, CreateOrUpdate call fails at 09/27/24 11:10:05.875:

[FAILED] Expected success, but got an error:
...
  In [It] at: /home/prow/go/src/sigs.k8s.io/cluster-api/test/e2e/clusterctl_upgrade.go:451 @ 09/27/24 11:10:05.875

but the CAPD logs are reflecting the webhook server as up at I0927 11:09:59.835554:

I0927 11:09:59.835554       1 server.go:242] "Serving webhook server" logger="controller-runtime.webhook" host="" port=9443`

so 6 seconds between the server as up and the call failing, not sure if we want to give the dry run approach a shot anyway? maybe we add collection of kube-system logs to further investigate this?

I see potentially a gap between Deployment being Available / Pod being Ready and kube-proxy updating iptables so the webhook is actually reachable.

sbueringer commented 1 month ago

I'm fine with giving the dry-run approach a shot. I think it's the easiest way for us to verify that the webhooks of all controllers are actually reachable.

I don't expect that we'll see much in kube-proxy logs (but could be). I'm fine with also collecting logs from kube-system. Could be useful in general (e.g. kube-apiserver logs could be quite useful)

cahillsf commented 6 days ago

circling back to this @sbueringer now the most frequent flake (https://github.com/kubernetes-sigs/cluster-api/issues/11133#issuecomment-2427763004) is only occurring on release-1.8 branches: https://storage.googleapis.com/k8s-triage/index.html?date=2024-11-18&text=connect%3A%20connection%20refused&job=.*periodic-cluster-api-e2e.*&test=.*clusterctl%20upgrades

so it seems this dry-run approach worked

(last flake on main is visible on this timeline and occurred 10/28 prior to the dry-run update merge on 10/29). do you think that is enough data to backport the changes to release-1.8?

BenTheElder commented 6 days ago

[I'm still lurking here but there's been a lot going on and it seems like you all are making progress 😅]

cahillsf commented 6 days ago

no conclusions, but adding some findings re:

2 Failures: x509: certificate signed by unknown authority

taking one specific example (have observed similar patterns in other failures) the test fails while migrating the CRs in the UpgradeManagementClusterAndWait process initiated here in the e2e test from v0.4.8 -> v1.6.8.

Note: the CRs are migrated before any changes are rolled out to the providers

looking at the CAPD controller logs, we can see they start filling up with these errors shortly after the upgrade command is run:

2024/11/02 01:44:37 http: TLS handshake error from 10.244.0.1:28755: remote error: tls: bad certificate
2024/11/02 01:44:38 http: TLS handshake error from 10.244.0.1:20689: remote error: tls: bad certificate
2024/11/02 01:44:39 http: TLS handshake error from 10.244.0.1:29264: remote error: tls: bad certificate
2024/11/02 01:44:40 http: TLS handshake error from 10.244.0.1:10669: remote error: tls: bad certificate

the migration eventually times with this line @ 11/02/24 01:45:01.663:

Error: failed to migrate clusterctl-upgrade/clusterctl-upgrade-workload-zszpga-control-plane: action failed after 10 attempts: Internal error occurred: failed calling webhook "validation.dockermachinetemplate.infrastructure.cluster.x-k8s.io": failed to call webhook: Post "https://capd-webhook-service.capd-system.svc:443/validate-infrastructure-cluster-x-k8s-io-v1alpha4-dockermachinetemplate?timeout=10s": x509: certificate signed by unknown authority

before the log stream cuts off, we can see these logs in the CAPD manager:

I1102 01:45:18.422998       1 deleg.go:130] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I1102 01:45:18.423382       1 deleg.go:130] controller-runtime/certwatcher "msg"="Updated current TLS certificate"

not exactly sure where to go next with this -- this v0.4.8 version is using sigs.k8s.io/controller-runtime v0.9.7 maybe there is some issue with the certwatcher in this version?

sbueringer commented 5 days ago

(last flake on main is visible on this timeline and occurred 10/28 prior to the dry-run update merge on 10/29). do you think that is enough data to backport the changes to release-1.8?

Absolutely

sbueringer commented 5 days ago

@cahillsf probably related: https://github.com/kubernetes-sigs/cluster-api/issues/10522

The best idea I have is rerunning clusterctl upgrade if we hit this error (but of course only for clusterctl v0.4.x because we can't fix it anymore)

@chrischdi wdyt?

chrischdi commented 5 days ago

@cahillsf probably related: #10522

The best idea I have is rerunning clusterctl upgrade if we hit this error (but of course only for clusterctl v0.4.x because we can't fix it anymore)

@chrischdi wdyt?

This is testing the upgrade from v0.4.8 to v1.6.8 right? So the upgrade is done using clusterctl v1.6.8. So its about rerunning on v1.6.8.

Retrying clusterctl upgrade may help and maybe is the easiest 👍 .

Just to take a step back:

Another approach when retrying clusterctl upgrade is not good enough may be to run out-of-band the cert-manager upgrade (and upgrade to the same or a more recent version?!) + directly the CR migration including retries.

Afterwards run the normal clusterctl upgrade as before.

Note: and only for upgrades to v1.6.x :-)

Offtopic: Shoutout to @cahillsf and others involved, awesome progress here! ❤️

sbueringer commented 5 days ago

Yeah, just had this thought. The clusterctl version that we can't fix shouldn't be v0.4 but a newer one

sbueringer commented 5 days ago

@chrischdi Can we simply backport the longer timeout that you introduced in #10513 into release-1.7 and release-1.6?

Do we know if that issue also occurs in tests that use clusterctl v1.5?

If not I would consider doing one additional v1.6.x release and then we're good (we still have ProwJobs for release-1.6)

chrischdi commented 5 days ago

+1 on backporting that and also cut a v1.6.9 for this.

But v1.5 seems also to be affected:

link

chrischdi commented 5 days ago

so maybe: