Looking for solution to clear the " waiting for etcd restore " and "Error applying plan -- check rancher-system-agent.service logs on node for more information " alert from the managed cluster.

[DipindasThayyil]

Looking for solution to clear the " waiting for etcd restore " and "Error applying plan -- check rancher-system-agent.service logs on node for more information " alert from the managed cluster.

Because of these alert, having difficulty to re-register the nodes into the cluster.

[brandond]

Did you do what it says and check those logs?

[DipindasThayyil]

restore was stuck with faulty nodes, I did remove that node, and it is proceeded further, however cluster restore failed.

So I removed all the faulty nodes and did restore again for the single control plane , after this I'm getting watiting for retcd restore probes message.

Any further suggestions ?

[brandond]

Yes, as before, check the logs on the node. You're providing zero information on what is actually going on. It is impossible to troubleshoot anything based on a brief description of a message in the Rancher UI.

[DipindasThayyil]

I appreciate @brandond for your support here and here is the summary of the issue.

I am trying to restore the cluster from the etcd backup; however, cluster restore is in stuck state with " waiting for etcd restore probes " error.

To fix the issue, I've tried with restarting the etcd container and rle2-server service, but no luck as of now.

Moreover,the same message is written in the Provisioned log, and I didn't reference failures messages for rke2-server or etcd container logs. Therefore, looking for a suggestion

From Provisioned log:
[INFO ] waiting for etcd restore probes

From the Conditions :

[DipindasThayyil]

Few more detail

root@prd-m3: /var/lib/rancher/agent# /var/lib/rancher/rke2/bin/crictl --config /var/lib/rancher/rke2/agent/etc/crictl.yaml ps
CONTAINER IMAGE CREATED STATE NAME ATTEMPT POD ID POD
9af2782323d00 b7e03d90f06bb 2 hours ago Running kube-proxy 0 bec4b5eca1f37 kube-proxy-prd-m3
6d3af9ba25d64 3525a3daa55c9 2 hours ago Running cloud-controller-manager 0 248b90a99d7f4 cloud-controller-manager-prd-m3
baeff0df8bd07 b7e03d90f06bb 2 hours ago Running kube-controller-manager 0 23d5e43a5c17a kube-controller-manager-prd-m3
037c4c7f6966b b7e03d90f06bb 2 hours ago Running kube-scheduler 0 6c40291a3e138 kube-scheduler-prd-m3
b799ec2fa4e7b b7e03d90f06bb 2 hours ago Running kube-apiserver 0 936a3b161c1ca kube-apiserver-prd-m3
ff9b56351b41c 7893f7425a52a 2 hours ago Running etcd 0 edb4bc240cf92 etcd-ssmo-prd-m3

root@prd-m3:/var/lib/rancher/agent# /var/lib/rancher/rke2/bin/kubectl get nodes
NAME STATUS ROLES AGE VERSION
prd-m3 Ready control-plane,etcd,master 95d v1.28.10+rke2r1
prd-m3 Ready worker 95d v1.28.10+rke2r1

As per the etcd container logs , it is complaining about the cerficate for the deleted node.

{"level":"warn","ts":"2024-10-29T20:24:37.914349Z","caller":"embed/config_logging.go:169","msg":"rejected connection","remote-addr":"10.244.122.83:55718","server-name":"","error":"remote error: tls: bad certificate"}

In M3 node , etcd is working and it is leader .

root@prd-m3:/var/lib/rancher/agent# export CRI_CONFIG_FILE=/var/lib/rancher/rke2/agent/etc/crictl.yaml
etcdcontainer=$(/var/lib/rancher/rke2/bin/crictl ps --label io.kubernetes.container.name=etcd --quiet)
/var/lib/rancher/rke2/bin/crictl exec $etcdcontainer etcdctl --cert /var/lib/rancher/rke2/server/tls/etcd/server-client.crt --key /var/lib/rancher/rke2/server/tls/etcd/server-client.key --cacert /var/lib/rancher/rke2/server/tls/etcd/server-ca.crt endpoint status --cluster --write-out=table
+-----------------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+
| ENDPOINT | ID | VERSION | DB SIZE | IS LEADER | IS LEARNER | RAFT TERM | RAFT INDEX | RAFT APPLIED INDEX | ERRORS |
+-----------------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+
| https://10.244.122.125:2379 | 66963b0acb1aef63 | 3.5.9 | 16 MB | true | false | 3 | 25628 | 25628 | |
+-----------------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+

[brandond]

NAME STATUS ROLES AGE VERSION
prd-m3 Ready control-plane,etcd,master 95d v1.28.10+rke2r1
prd-m3 Ready worker 95d v1.28.10+rke2r1

According to this output you have two nodes with the same name, which is not possible. Are you redacting or otherwise editing your command output?

As per the etcd container logs , it is complaining about the cerficate for the deleted node.

{"level":"warn","ts":"2024-10-29T20:24:37.914349Z","caller":"embed/config_logging.go:169","msg":"rejected connection","remote-addr":"10.244.122.83:55718","server-name":"","error":"remote error: tls: bad certificate"}

While this should be a harmless warning, it does indicate that etcd is still running on the "deleted" node. Please confirm that you have powered down or at least run the rke2-killall.sh script on the "deleted" nodes.

[DipindasThayyil]

There was a typo in the kubectl get node command, here is the correct one.

root@prd-m3:~# export KUBECONFIG=/etc/rancher/rke2/rke2.yaml
/var/lib/rancher/rke2/bin/kubectl get nodes
NAME STATUS ROLES AGE VERSION
prd-m3 Ready control-plane,etcd,master 95d v1.28.10+rke2r1
prd-w2 Ready worker 95d v1.28.10+rke2r1

Even I have checked on RKE2 Hub cluster and there I observed the "running etcd restore" message for " kubectl get cluster prd-cluster -n fleet-default -o yaml" command output.

paused: true
status:
conditions:

• lastTransitionTime: "2024-07-26T13:50:21Z"
  status: "True"
  type: Ready
• lastTransitionTime: "2024-07-26T13:59:58Z"
  status: "True"
  type: ControlPlaneInitialized
• lastTransitionTime: "2024-10-26T15:39:46Z"
  message: cluster shutdown complete, running etcd restore
  reason: Waiting
  status: Unknown
  type: ControlPlaneReady
• lastTransitionTime: "2024-07-26T13:50:21Z"
  status: "True"
  type: InfrastructureReady
  controlPlaneReady: false
  infrastructureReady: true
  observedGeneration: 584896
  phase: Provisioned

Is anything else I've to review? Morever any suggestions on the " [Waiting] waiting for etcd restore probes " error ?

[brandond]

You're still not providing any information from the logs on the node. Specifically, the rancher-system-agent and rke2-server logs in journald. See what it's doing and what it's waiting for.

[DipindasThayyil]

Apologies here ,

To clear " [Waiting] waiting for etcd restore probes " error, I've restored etcd from the local backup then followed below step to bring the etcd on single/working node. However cluster is in updating phase with new error" configuring bootstrap node(s) custom-c96cf0a4d7ef: error applying plan -- check rancher-system-agent.service logs on node for more information, failure while applying plan "

rke2 server --cluster-reset

For further check , I've reviewed rke2-server.service & rancher-system-agent.service logs.

root@prd-m3:/var/lib/rancher/rke2/server/db/snapshots# kubectl get node
NAME STATUS ROLES AGE VERSION
prd-m3 Ready control-plane,etcd,master 96d v1.28.10+rke2r1
prd-w2 Ready worker 96d v1.28.10+rke2r1
root@prd-m3:/var/lib/rancher/rke2/server/db/snapshots# crictl ps
CONTAINER IMAGE CREATED STATE NAME ATTEMPT POD ID POD
dd0590a07c1f9 abc5338582c4f 28 minutes ago Running system-upgrade-controller 2 20be07d08db47 system-upgrade-controller-6f86d6d4df-62klm
a05e7c58d0717 5c6ffd2b2a1d0 28 minutes ago Running calico-node 3 747f159f28998 calico-node-p7pk9
4311341227671 b7e03d90f06bb 28 minutes ago Running kube-proxy 5 429126f81ed86 kube-proxy-prd-m3
55dbe6505de0c 3525a3daa55c9 28 minutes ago Running cloud-controller-manager 0 3fe10c3101f9c cloud-controller-manager-prd-m3
f065d6bc48741 b7e03d90f06bb 28 minutes ago Running kube-scheduler 0 825aaf831d2f1 kube-scheduler-prd-m3
db96e29f1bd4b b7e03d90f06bb 28 minutes ago Running kube-controller-manager 0 f510df9cea1e4 kube-controller-manager-prd-m3
5980bd633b571 b7e03d90f06bb 28 minutes ago Running kube-apiserver 0 af76fca209739 kube-apiserver-prd-m3
1014e90370c73 7893f7425a52a 28 minutes ago Running etcd 0 28b534e2aa91f etcd-prd-m3

root@prd-m3:/var/lib/rancher/rke2/server/db/snapshots# journalctl -f -u rke2-server
Oct 30 10:01:06 prd-m3 rke2[221395]: time="2024-10-30T10:01:06-04:00" level=info msg="Checking if S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:01:06 prd-m3 rke2[221395]: time="2024-10-30T10:01:06-04:00" level=info msg="S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:01:39 prd-m3 rke2[221395]: time="2024-10-30T10:01:39-04:00" level=info msg="Checking if S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:01:39 prd-m3 rke2[221395]: time="2024-10-30T10:01:39-04:00" level=info msg="S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:02:11 prd-m3 rke2[221395]: time="2024-10-30T10:02:11-04:00" level=info msg="Checking if S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:02:11 prd-m3 rke2[221395]: time="2024-10-30T10:02:11-04:00" level=info msg="S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:02:44 prd-m3 rke2[221395]: time="2024-10-30T10:02:44-04:00" level=info msg="Checking if S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:02:44 prd-m3 rke2[221395]: time="2024-10-30T10:02:44-04:00" level=info msg="S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:03:15 prd-m3 rke2[221395]: time="2024-10-30T10:03:15-04:00" level=info msg="Checking if S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:03:15 prd-m3 rke2[221395]: time="2024-10-30T10:03:15-04:00" level=info msg="S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:03:46 prd-m3 rke2[221395]: time="2024-10-30T10:03:46-04:00" level=info msg="Checking if S3 bucket rke-etcd-prod-backup-s3 exists"
Oct 30 10:03:46 prd-m3 rke2[221395]: time="2024-10-30T10:03:46-04:00" level=info msg="S3 bucket rke-etcd-prod-backup-s3 exists"

According to the rancher-system-agent.service journalctl logs it is reporting " msg="[Applyinator] Command sh [-c rke2 etcd-snapshot list --etcd-s3 2>/dev/null] finished with err: and exit code: 0" "

More details :
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m1-1730088002 s3://rke-etcd-prod-backup-s3/ssmo-prd-hop/etcd-snapshot-prd-m1-1730088002 17854496 2024-10-28T00:00:02-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m3-1730088005 s3://rke-etcd-prod-backup-s3/ssmo-prd-hop/etcd-snapshot-prd-m3-1730088005 17682464 2024-10-28T00:00:05-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m3-1730088005 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730088005 17682464 2024-10-28T00:00:05-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m1-1730174402 s3://rke-etcd-prod-backup-s3/ssmo-prd-hop/etcd-snapshot-prd-m1-1730174402 17854496 2024-10-29T00:00:02-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m3-1730174402 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730174402 17682464 2024-10-29T00:00:02-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m3-1730174402 s3://rke-etcd-prod-backup-s3/ssmo-prd-hop/etcd-snapshot-prd-m3-1730174402 17682464 2024-10-29T00:00:02-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m3-1730260802 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730260802 16240672 2024-10-30T00:00:02-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[3b3c35400b09c30cab6df77b12a3b748e47050c52afc4391bdc89928d696a0ca_1:stdout]: etcd-snapshot-prd-m3-1730260802 s3://rke-etcd-prod-backup-s3/ssmo-prd-hop/etcd-snapshot-prd-m3-1730260802 16240672 2024-10-30T00:00:02-04:00"
Oct 30 10:11:36 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:36-04:00" level=info msg="[Applyinator] Command sh [-c rke2 etcd-snapshot list --etcd-s3 2>/dev/null] finished with err: and exit code: 0"

Oct 30 10:11:37 prd-m3 rancher-system-agent[220535]: time="2024-10-30T10:11:37-04:00" level=info msg="[K8s] updated plan secret fleet-default/custom-c96cf0a4d7ef-machine-plan with feedback"

Accord to the logs everything is pointing into s3 backup path and cluster is running with single node etcd and there is no dependency with s3. Is there is possible to clear the S3 dependency ?

Right now I've edited the cluster config and disabled the Backup snapshot to s3 option.

new logs from "journalctl -f -u rancher-system-agent":

Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[20b3f0c1d002b8618c8999bfdd8e794f1bc33b2b4779395f1509c6d02149bac8_0:stdout]: etcd-snapshot-prd-m3-1729224005 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1729224005 20717600 2024-10-18T00:00:05-04:00"
Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[20b3f0c1d002b8618c8999bfdd8e794f1bc33b2b4779395f1509c6d02149bac8_0:stdout]: etcd-snapshot-prd-m3-1729915203 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1729915203 14024736 2024-10-26T00:00:03-04:00"
Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[20b3f0c1d002b8618c8999bfdd8e794f1bc33b2b4779395f1509c6d02149bac8_0:stdout]: etcd-snapshot-prd-m3-1730001602 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730001602 17682464 2024-10-27T00:00:02-04:00"
Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[20b3f0c1d002b8618c8999bfdd8e794f1bc33b2b4779395f1509c6d02149bac8_0:stdout]: etcd-snapshot-prd-m3-1730088005 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730088005 17682464 2024-10-28T00:00:05-04:00"
Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[20b3f0c1d002b8618c8999bfdd8e794f1bc33b2b4779395f1509c6d02149bac8_0:stdout]: etcd-snapshot-prd-m3-1730174402 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730174402 17682464 2024-10-29T00:00:02-04:00"
Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[20b3f0c1d002b8618c8999bfdd8e794f1bc33b2b4779395f1509c6d02149bac8_0:stdout]: etcd-snapshot-prd-m3-1730260802 file:///var/lib/rancher/rke2/server/db/snapshots/etcd-snapshot-prd-m3-1730260802 16240672 2024-10-30T00:00:02-04:00"
Oct 30 10:50:15 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:15-04:00" level=info msg="[Applyinator] Command sh [-c rke2 etcd-snapshot list --etcd-s3=false 2>/dev/null] finished with err: and exit code: 0"
Oct 30 10:50:17 prd-m3 rancher-system-agent[256510]: time="2024-10-30T10:50:17-04:00" level=info msg="[K8s] updated plan secret fleet-default/custom-c96cf0a4d7ef-machine-plan with feedback"

Even I've reviewed secret custom-c96cf0a4d7ef-machine-plan in Main hub cluster and I didn't find anything.

Moreover I'm looking for further suggestion here to bring the cluster online

[brandond]

If you manually restored the snapshot without involving the system agent, it probably thinks that the restore failed since it was unable to complete the process itself. Look further back in the rancher system agent logs to see what failed.