Repository navigation
Kubelet gets "Timeout: Too large resource version" error from the API server after network outage #91073
Description
What happened:
I have disconnected a node from network for a few minutes. After reconnecting, I keep receiving such error messages from kubelet on the node, even after 15 minutes in reconnected state:
May 13 19:44:54 k8s-node04 kubelet[598]: I0513 19:44:54.043005 598 trace.go:116] Trace[1747581308]: "Reflector ListAndWatch" name:object-"kube-system"/"default-token-h8dz9" (started: 2020-05-13 19:44:14.938918643 +0000 UTC m=+81978.107654790) (total time: 39.10398118s):
May 13 19:44:54 k8s-node04 kubelet[598]: Trace[1747581308]: [39.10398118s] [39.10398118s] END
May 13 19:44:54 k8s-node04 kubelet[598]: E0513 19:44:54.043090 598 reflector.go:178] object-"kube-system"/"default-token-h8dz9": Failed to list *v1.Secret: Timeout: Too large resource version: 159128021, current: 159127032
May 13 19:45:16 k8s-node04 kubelet[598]: I0513 19:45:16.944515 598 trace.go:116] Trace[527369896]: "Reflector ListAndWatch" name:k8s.io/client-go/informers/factory.go:135 (started: 2020-05-13 19:44:37.84920601 +0000 UTC m=+82001.017941865) (total time: 39.095209656s):
May 13 19:45:16 k8s-node04 kubelet[598]: Trace[527369896]: [39.095209656s] [39.095209656s] END
May 13 19:45:16 k8s-node04 kubelet[598]: E0513 19:45:16.944595 598 reflector.go:178] k8s.io/client-go/informers/factory.go:135: Failed to list *v1beta1.RuntimeClass: Timeout: Too large resource version: 159128061, current: 159127066
May 13 19:45:23 k8s-node04 kubelet[598]: I0513 19:45:23.959866 598 trace.go:116] Trace[243135295]: "Reflector ListAndWatch" name:k8s.io/kubernetes/pkg/kubelet/kubelet.go:517 (started: 2020-05-13 19:44:44.860565979 +0000 UTC m=+82008.029301834) (total time: 39.099201281s):
May 13 19:45:23 k8s-node04 kubelet[598]: Trace[243135295]: [39.099201281s] [39.099201281s] END
May 13 19:45:23 k8s-node04 kubelet[598]: E0513 19:45:23.959947 598 reflector.go:178] k8s.io/kubernetes/pkg/kubelet/kubelet.go:517: Failed to list *v1.Service: Timeout: Too large resource version: 159128031, current: 159127042
May 13 19:45:32 k8s-node04 kubelet[598]: I0513 19:45:32.752744 598 trace.go:116] Trace[1950236492]: "Reflector ListAndWatch" name:k8s.io/client-go/informers/factory.go:135 (started: 2020-05-13 19:44:53.65385557 +0000 UTC m=+82016.822591425) (total time: 39.098776276s):
May 13 19:45:32 k8s-node04 kubelet[598]: Trace[1950236492]: [39.098776276s] [39.098776276s] END
May 13 19:45:32 k8s-node04 kubelet[598]: E0513 19:45:32.752831 598 reflector.go:178] k8s.io/client-go/informers/factory.go:135: Failed to list *v1.CSIDriver: Timeout: Too large resource version: 159128079, current: 159127090
May 13 19:45:35 k8s-node04 kubelet[598]: I0513 19:45:35.670924 598 trace.go:116] Trace[1207388769]: "Reflector ListAndWatch" name:object-"kube-system"/"kube-router-token-4px26" (started: 2020-05-13 19:44:56.566459557 +0000 UTC m=+82019.735195412) (total time: 39.104363817s):
May 13 19:45:35 k8s-node04 kubelet[598]: Trace[1207388769]: [39.104363817s] [39.104363817s] END
May 13 19:45:35 k8s-node04 kubelet[598]: E0513 19:45:35.671005 598 reflector.go:178] object-"kube-system"/"kube-router-token-4px26": Failed to list *v1.Secret: Timeout: Too large resource version: 159128021, current: 159127032
May 13 19:46:05 k8s-node04 kubelet[598]: I0513 19:46:05.472918 598 trace.go:116] Trace[308823067]: "Reflector ListAndWatch" name:object-"kube-system"/"default-token-h8dz9" (started: 2020-05-13 19:45:26.359131486 +0000 UTC m=+82049.527867341) (total time: 39.113684635s):
May 13 19:46:05 k8s-node04 kubelet[598]: Trace[308823067]: [39.113684635s] [39.113684635s] END
May 13 19:46:05 k8s-node04 kubelet[598]: E0513 19:46:05.473007 598 reflector.go:178] object-"kube-system"/"default-token-h8dz9": Failed to list *v1.Secret: Timeout: Too large resource version: 159128021, current: 159127032
What you expected to happen:
I expect that after network recovery kubelet reconnects to the Apiserver as before, and after a recovery such timeouts do not occur.
How to reproduce it (as minimally and precisely as possible):
Just have a node connected to the cluster. Then, disconnect it from the network for 3-4 minutes, then reconnect. Then observe kubelet's logs.
Anything else we need to know?:
I have strict tcp keepalive settings in place on master and worker nodes, but this should not be the cause.
# sysctl -a|grep net.ipv4|grep tcp_keep
net.ipv4.tcp_keepalive_intvl = 10
net.ipv4.tcp_keepalive_probes = 9
net.ipv4.tcp_keepalive_time = 600
Restarting kubelet solves the issue, the error messages disappear.
Environment:
- Kubernetes version (use
kubectl version):
$ kubectl version
Client Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.2", GitCommit:"52c56ce7a8272c798dbc29846288d7cd9fbae032", GitTreeState:"clean", BuildDate:"2020-04-16T11:56:40Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.2", GitCommit:"52c56ce7a8272c798dbc29846288d7cd9fbae032", GitTreeState:"clean", BuildDate:"2020-04-16T11:48:36Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/arm"}
- Cloud provider or hardware configuration:
bare metal - OS (e.g:
cat /etc/os-release):
# cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
- Kernel (e.g.
uname -a):
# uname -a
Linux k8s-node04 5.4.40 #2 SMP Sun May 10 13:03:41 UTC 2020 aarch64 GNU/Linux
- Install tools:
kubeadm - Network plugin and version (if this is a network-related bug):
kube-router - Others:
Activity
rkojedzinszky commentedon May 13, 2020
/sig api-machinery
rkojedzinszky commentedon May 13, 2020
/sig api-machinery
rkojedzinszky commentedon May 14, 2020
It seems that after some more time, kubelet recovers. Sometimes it takes one hour, sometimes two. Recovery is successful when I receive similar logs:
What is the reason that it takes so long for it to recover?
liggitt commentedon May 14, 2020
The root cause is #82428, deduplicating against that issue
rkojedzinszky commentedon May 24, 2020
Debugging, tracing the code, I am not really sure that this is the same issue as the other mentioned here.
Error messages show that the client is requesting higher resource versions that is available at the server:
159128021, current: 159127032, the former is greater by 989 than the latter. I dont know from where this resource version comes from.I've made a very stupid patch on my kubelet/client-go:
I am pretty sure that this is not the best solution, but, it seems that it forces a full list every time ListAndWatch is called.
liggitt commentedon Jun 1, 2020
You're correct, sorry about that... I misread the timeout message.
The error it is getting is coming from the server, which means kubelet -> apiserver connectivity is fine.
This message comes from the watch cache, which means the watch cache in the API server is behind where the kubelet's informer was, which is pretty surprising.
A few questions:
[-]Kubelet fails to reconnect to Apiserver after network outage[/-][+]Kubelet gets "Timeout: Too large resource version" error from the API server after network outage[/+]liggitt commentedon Jun 1, 2020
cc @jpbetz does this ring any bells?
11 remaining items
rkojedzinszky commentedon Jun 25, 2020
Today I have re-initialized 2 of my 3 master nodes to make sure etcd replicas are not corrupted. Just after the nodes have been joined, the same behavior could be observed: connecting to different masters resulted in different resourceVersions.
rkojedzinszky commentedon Jun 25, 2020
Now, it can be seen, that querying different apiservers again return different resourceVersions:
192.168.8.60:16443 is a haproxy load-balancing traffic between 3 masters.
rkojedzinszky commentedon Jun 25, 2020
@wojtek-t @jpbetz please let me know where to go further. My cluster runs on PI boards, perhaps, not the fastest ones. But if this issue depends on slow hardware, than it can pop up anytime on fast hardware as well.As I wrote, today I reinitialized 2 of my 3 masters to make sure no partitioning occured. Also, please have a look at my comments. Or, if you have a clue that my setup is broken, please let me know!
rkojedzinszky commentedon Jun 25, 2020
It seems that it happens to resources where no objects exist at all. Can it be?
wojtek-t commentedon Jun 26, 2020
Ahh - the fact tht it happens for types with no objects actually made me know what is happening here.
Basically what is happening is that when kube-apiserver is starting, watchcache is initialized from "now" (i.e. it will be synced to resource version that was globally last in etcd at the time when it was initialized).
However, later it's updated only on changes of resources of those types. So when no objects of that type is being added/modified/deleted it will stay the same.
So it's kind-of "working-as-implemented" from the kube-apiserver perspective. That can be improved - I'm actually already looking into reusing etcd progress-notify feature to get rid of this behavior (#86769 & #92472) - I would like to have alpha for that in 1.20 and beta in 1.21 (planning to write down KEP once I'm back from my soon-starting vacation), but that shouldn't be the problem by itself. And it's not what is really biting you.
The real problem is that there is a bug in reflector in:
https://github.com/kubernetes/kubernetes/blob/release-1.18/staging/src/k8s.io/client-go/tools/cache/reflector.go#L259
It handled the "too old RV" error, but it doesn't handle "too large RV" correctly. What it should be doing instead is to:
Watch will work fine because watch will simply wait until events with larger RV appear.
I will send out a PR fixing that bug (will try to do it later today).
wojtek-t commentedon Jun 26, 2020
#92537 is out for review
wojtek-t commentedon Jul 1, 2020
This has been fixed/mitigated in 1.18. Going to backport to 1.18 now.
It seems 1.18 is the first version affected (the offending changes were reverted in 1.17 months ago).
wojtek-t commentedon Jul 27, 2020
This has been mitigated in 1.18 and head.
The more proper fix is proposed in kubernetes/enhancements#1878
Closing this one.
go.mod: Vendor newer prometheus and k8s
go.mod: Vendor newer prometheus and k8s (#990)
nerzhul commentedon Nov 9, 2020
Hello, as i saw, i have the same issue in 1.19.3 version:
Our setup is 3 etcd, 2 apiserver bound on those 3 etcd and a haproxy in front of apiservers
wojtek-t commentedon Nov 10, 2020
If that happens once - that can definitely happen (and that's fine). The bug was that the components were stuck with those errors.
oldthreefeng commentedon Apr 1, 2021
1.18.0 get same error . restart docker and kubelet return OK.
so , should I update the 1.18.0 to 1.18.6+ ?