Description
Hello
I am using CAPI to manage setting up new kubernetes clusters
In my environment I am encountering an issue where I try to setup a 3 node controlplane but get stuck after adding the second node.
In the kcp logs this error repeats
E0121 13:25:32.061001 1 controller.go:316] "Reconciler error" err="failed to get etcdStatus for workload cluster obj-store-01: failed to create etcd client: etcd leader is reported as bc116290b8a83a52 with name \"obj-store-01-wchl9\", but we couldn't find a corresponding Node in the cluster" controller="kubeadmcontrolplane" controllerGroup="controlplane.cluster.x-k8s.io" controllerKind="KubeadmControlPlane" KubeadmControlPlane="minio-default/obj-store-01" namespace="minio-default" name="obj-store-01" reconcileID="75ed1ba2-fd8c-43a3-bd16-2ced8db56999"
The etcd member table looks like this
+------------------+---------+--------------------+-----------------------------+-----------------------------+------------+
| ID | STATUS | NAME | PEER ADDRS | CLIENT ADDRS | IS LEARNER |
+------------------+---------+--------------------+-----------------------------+-----------------------------+------------+
| 785b2d66a9ca13ed | started | obj-store-01-gd6dn | https://SOME_IP:2380 | https://SOME_IP:2379 | false |
| bc116290b8a83a52 | started | obj-store-01-wchl9 | https://SOME_OTHER_IP:2380 | https://SOME_OTHER_IP:2379 | false |
+------------------+---------+--------------------+-----------------------------+-----------------------------+------------+
If i look at the cloud-init-output log for node obj-store-01-wchl9 it terminates with an error
[2025-01-21 12:14:31] {"level":"warn","ts":"2025-01-21T12:14:31.940653Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: request timed out, waiting for the applied index took too long"}
[2025-01-21 12:14:37] {"level":"warn","ts":"2025-01-21T12:14:37.958044Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
[2025-01-21 12:14:45] {"level":"warn","ts":"2025-01-21T12:14:45.689035Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
[2025-01-21 12:14:53] [kubelet-check] Initial timeout of 40s passed.
[2025-01-21 12:14:56] {"level":"warn","ts":"2025-01-21T12:14:56.933405Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
[2025-01-21 12:15:10] {"level":"warn","ts":"2025-01-21T12:15:10.318514Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
[2025-01-21 12:15:31] {"level":"warn","ts":"2025-01-21T12:15:31.439807Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
[2025-01-21 12:16:03] {"level":"warn","ts":"2025-01-21T12:16:03.125611Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
[2025-01-21 12:16:49] {"level":"warn","ts":"2025-01-21T12:16:49.883513Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
[2025-01-21 12:18:02] {"level":"warn","ts":"2025-01-21T12:18:02.221299Z","logger":"etcd-client","caller":"[email protected]/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0000d68c0/SOME_IP:2379","attempt":0,"error":"rpc error: code = FailedPrecondition desc = etcdserver: can only promote a learner member"}
So it appears that we had added an etcd member as a learner and then were attempting to promote it.
One of the calls to promote times out but succeeded on the backend, causing all future calls to promote to fail
I found this recent PR that addresses a similar issue kubernetes/kubernetes#127491 but would not address the problem I'm seeing
In the latest kubeadm the MemberPromote now looks like this
// MemberPromote promotes a member as a voting member. If the given member ID is already a voting member this method
// will return early and do nothing.
func (c *Client) MemberPromote(learnerID uint64) error {
isLearner, err := c.isLearner(learnerID)
if err != nil {
return err
}
if !isLearner {
klog.V(1).Infof("[etcd] Member %s already promoted.", strconv.FormatUint(learnerID, 16))
return nil
}
klog.V(1).Infof("[etcd] Promoting a learner as a voting member: %s", strconv.FormatUint(learnerID, 16))
cli, err := c.newEtcdClient(c.Endpoints)
if err != nil {
return err
}
defer func() { _ = cli.Close() }()
// TODO: warning logs from etcd client should be removed.
// The warning logs are printed by etcd client code for several reasons, including
// 1. can not promote yet(no synced)
// 2. context deadline exceeded
// 3. peer URLs already exists
// Once the client provides a way to check if the etcd learner is ready to promote, the retry logic can be revisited.
var (
lastError error
)
err = wait.PollUntilContextTimeout(context.Background(), constants.EtcdAPICallRetryInterval, constants.EtcdAPICallTimeout,
true, func(_ context.Context) (bool, error) {
ctx, cancel := context.WithTimeout(context.Background(), etcdTimeout)
defer cancel()
_, err = cli.MemberPromote(ctx, learnerID) <=== We need an are we promoted check here as well
if err == nil {
klog.V(1).Infof("[etcd] The learner was promoted as a voting member: %s", strconv.FormatUint(learnerID, 16))
return true, nil
}
klog.V(5).Infof("[etcd] Promoting the learner %s failed: %v", strconv.FormatUint(learnerID, 16), err)
lastError = err
return false, nil
})
if err != nil {
return lastError
}
return nil
}
What I would like to do is add an additional check within the wait.PollUntilContextTimeout
func so that it checks if the member has been promoted before every attempt to promote. If the member has already been promoted it should return early
i.e. reuse this code from earlier in the function
isLearner, err := c.isLearner(learnerID)
if err != nil {
return err
}
if !isLearner {
klog.V(1).Infof("[etcd] Member %s already promoted.", strconv.FormatUint(learnerID, 16))
return nil
}
Ideally etcd cluster wouldnt return a timeout message when the op actually succeeded, but I would like to add this extra check regardless as I think its fairly low risk. How would I go about adding it?