retrying of unary invoker failed

[sumlittle]

I tried to build a k8s cluster on rocky linux 9.4 based on VM deployment. The corresponding cluster information is as follows:

Master

Host name: k8s1

IP address: 192.168.139.129

Node

Host name: k8s2

IP address: 192.168.139.139

Host name: k8s3

IP address: 192.168.139.149

System version: rocky linux: 9.4

etcdctl version

• etcdctl version: 3.5.12
• API version: 3.5

Etcd configuration (command line flags or environment variables)
The corresponding k8s1 configuration file is as follows:

name: 'etcd1'
data-dir: '/var/lib/etcd'
listen-peer-urls: 'https://192.168.139.129:2380'
listen-client-urls: 'https://192.168.139.129:2379'
advertise-client-urls: 'https://192.168.139.129:2379'
initial-advertise-peer-urls: 'https://192.168.139.129:2380'
initial-cluster: 'etcd1=https://192.168.139.129:2380,etcd2=https://192.168.139.139:2380,etcd3=https://192.168.139.149:2380'
initial-cluster-state: 'new'
initial-cluster-token: 'etcd-cluster'
client-transport-security:
  cert-file: /etc/kubernetes/pki/etcd/etcd-server.pem
  key-file: /etc/kubernetes/pki/etcd/etcd-server-key.pem
  client-cert-auth: true
  trusted-ca-file: /etc/kubernetes/pki/etcd/etcd-ca.pem
peer-transport-security:
  cert-file: /etc/kubernetes/pki/etcd/etcd-peer.pem
  key-file: /etc/kubernetes/pki/etcd/etcd-peer-key.pem
  peer-client-cert-auth: true
  trusted-ca-file: /etc/kubernetes/pki/etcd/etcd-ca.pem

The corresponding k8s2 configuration file is as follows:

name: 'etcd2'
data-dir: '/var/lib/etcd'
listen-peer-urls: 'https://192.168.139.139:2380'
listen-client-urls: 'https://192.168.139.139:2379'
advertise-client-urls: 'https://192.168.139.139:2379'
initial-advertise-peer-urls: 'https://192.168.139.139:2380'
initial-cluster: 'etcd1=https://192.168.139.129:2380,etcd2=https://192.168.139.139:2380,etcd3=https://192.168.139.149:2380'
initial-cluster-state: 'new'
initial-cluster-token: 'etcd-cluster'
client-transport-security:
  cert-file: /etc/kubernetes/pki/etcd/etcd-server.pem
  key-file: /etc/kubernetes/pki/etcd/etcd-server-key.pem
  client-cert-auth: true
  trusted-ca-file: /etc/kubernetes/pki/etcd/etcd-ca.pem
peer-transport-security:
  cert-file: /etc/kubernetes/pki/etcd/etcd-peer.pem
  key-file: /etc/kubernetes/pki/etcd/etcd-peer-key.pem
  peer-client-cert-auth: true
  trusted-ca-file: /etc/kubernetes/pki/etcd/etcd-ca.pem

The corresponding k8s3 configuration file is as follows:

name: 'etcd3'
data-dir: '/var/lib/etcd'
listen-peer-urls: 'https://192.168.139.149:2380'
listen-client-urls: 'https://192.168.139.149:2379'
advertise-client-urls: 'https://192.168.139.149:2379'
initial-advertise-peer-urls: 'https://192.168.139.149:2380'
initial-cluster: 'etcd1=https://192.168.139.129:2380,etcd2=https://192.168.139.139:2380,etcd3=https://192.168.139.149:2380'
initial-cluster-state: 'new'
initial-cluster-token: 'etcd-cluster'
client-transport-security:
  cert-file: /etc/kubernetes/pki/etcd/etcd-server.pem
  key-file: /etc/kubernetes/pki/etcd/etcd-server-key.pem
  client-cert-auth: true
  trusted-ca-file: /etc/kubernetes/pki/etcd/etcd-ca.pem
peer-transport-security:
  cert-file: /etc/kubernetes/pki/etcd/etcd-peer.pem
  key-file: /etc/kubernetes/pki/etcd/etcd-peer-key.pem
  peer-client-cert-auth: true
  trusted-ca-file: /etc/kubernetes/pki/etcd/etcd-ca.pem

When I check the relevant logs on node k8s1:

[root@k8s1 ~]# sudo journalctl -u etcd -f
Jul 15 16:26:37 k8s1 etcd[39854]: {"level":"warn","ts":"2024-07-15T16:26:37.389131+0800","caller":"etcdserver/raft.go:416","msg":"leader failed to send out heartbeat on time; took too long, leader is overloaded likely from slow disk","to":"79d3768762318bea","heartbeat-interval":"100ms","expected-duration":"200ms","exceeded-duration":"137.354439ms"}
Jul 15 16:26:37 k8s1 etcd[39854]: {"level":"warn","ts":"2024-07-15T16:26:37.598267+0800","caller":"etcdserver/raft.go:416","msg":"leader failed to send out heartbeat on time; took too long, leader is overloaded likely from slow disk","to":"ead9c4042afefabe","heartbeat-interval":"100ms","expected-duration":"200ms","exceeded-duration":"9.413419ms"}
Jul 15 16:26:37 k8s1 etcd[39854]: {"level":"warn","ts":"2024-07-15T16:26:37.598376+0800","caller":"etcdserver/raft.go:416","msg":"leader failed to send out heartbeat on time; took too long, leader is overloaded likely from slow disk","to":"79d3768762318bea","heartbeat-interval":"100ms","expected-duration":"200ms","exceeded-duration":"9.278224ms"}
Jul 16 09:27:06 k8s1 etcd[39854]: {"level":"info","ts":"2024-07-16T09:27:06.306295+0800","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"e96d62c0cd6c607e [logterm: 18, index: 703, vote: e96d62c0cd6c607e] ignored MsgPreVote from ead9c4042afefabe [logterm: 18, index: 703] at term 18: lease is not expired (remaining ticks: 2)"}
Jul 16 09:27:06 k8s1 etcd[39854]: {"level":"info","ts":"2024-07-16T09:27:06.354791+0800","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"e96d62c0cd6c607e [logterm: 18, index: 703, vote: e96d62c0cd6c607e] ignored MsgVote from ead9c4042afefabe [logterm: 18, index: 703] at term 18: lease is not expired (remaining ticks: 2)"}
Jul 16 09:27:06 k8s1 etcd[39854]: {"level":"info","ts":"2024-07-16T09:27:06.35578+0800","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"e96d62c0cd6c607e [term: 18] received a MsgHeartbeat message with higher term from ead9c4042afefabe [term: 19]"}
Jul 16 09:27:06 k8s1 etcd[39854]: {"level":"info","ts":"2024-07-16T09:27:06.361706+0800","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"e96d62c0cd6c607e became follower at term 19"}
Jul 16 09:27:06 k8s1 etcd[39854]: {"level":"info","ts":"2024-07-16T09:27:06.36239+0800","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"raft.node: e96d62c0cd6c607e changed leader from e96d62c0cd6c607e to ead9c4042afefabe at term 19"}
Jul 16 09:27:06 k8s1 etcd[39854]: {"level":"info","ts":"2024-07-16T09:27:06.463954+0800","logger":"raft","caller":"etcdserver/zap_raft.go:77","msg":"e96d62c0cd6c607e [logterm: 18, index: 703, vote: 0] rejected MsgPreVote from 79d3768762318bea [logterm: 18, index: 703] at term 19"}
Jul 16 09:49:27 k8s1 etcd[39854]: {"level":"warn","ts":"2024-07-16T09:49:27.823365+0800","caller":"embed/config_logging.go:169","msg":"rejected connection","remote-addr":"192.168.139.139:39022","server-name":"","error":"EOF"}

But my disk is normal:

[root@k8s1 ~]# df -h
iostat -xz 1 3
Filesystem           Size  Used Avail Use% Mounted on
devtmpfs             4.0M     0  4.0M   0% /dev
tmpfs                1.8G     0  1.8G   0% /dev/shm
tmpfs                726M   70M  656M  10% /run
/dev/mapper/rl-root   88G  6.3G   82G   8% /
/dev/nvme0n1p2       912M  309M  604M  34% /boot
/dev/nvme0n1p1       952M  7.1M  945M   1% /boot/efi
tmpfs                363M  4.0K  363M   1% /run/user/0
Linux 5.14.0-427.22.1.el9_4.x86_64 (k8s1)       07/16/2024      _x86_64_        (4 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
7.90    0.00    3.98    0.01    0.00   88.10
Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz     f/s f_await  aqu-sz  %util
dm-0             0.48     29.46     0.00   0.00    1.08    60.92    1.65     16.22     0.00   0.00    1.76     9.81    0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00    0.00   0.21
dm-1             0.00      0.07     0.00   0.00    0.57    21.57    0.00      0.00     0.00   0.00    0.00     0.00    0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00    0.00   0.00
nvme0n1          0.52     31.65     0.06  10.98    1.07    61.01    1.31     16.29     0.35  21.20    1.70    12.48    0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00    0.00   0.21
sr0              0.00      0.07     0.00   0.00    0.85    38.81    0.00      0.00     0.00   0.00    0.00     0.00    0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00    0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
3.37    0.00    8.29    0.00    0.00   88.34
Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz     f/s f_await  aqu-sz  %util

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
12.90    0.00   22.58    0.00    0.00   64.52

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz     f/s f_await  aqu-sz  %util

Check the cluster status as follows:

[root@k8s1 ~]# etcdctl --endpoints=https://192.168.139.129:2379 --cacert=/etc/kubernetes/pki/etcd/etcd-ca.pem --cert=/etc/kubernetes/pki/etcd/etcd-peer.pem --key=/etc/kubernetes/pki/etcd/etcd-peer-key.pem endpoint health
{"level":"warn","ts":"2024-07-16T10:04:19.399133+0800","logger":"client","caller":"v3@v3.5.12/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc0003e2540/192.168.139.129:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
https://192.168.139.129:2379 is unhealthy: failed to commit proposal: context deadline exceeded
Error: unhealthy cluster

Because I built it based on a VM, is it possible that this is the reason? Is there any solution?

[ahrtr]

Please generate a report using https://github.com/ahrtr/etcd-diagnosis

[lucky-long1]

@sumlittle the problem has been solved? I have the same issue.