Skip to content
This repository was archived by the owner on Jun 20, 2024. It is now read-only.

unreachable IPs in 2.5.0 #3600

Closed
JaveriaK opened this issue Feb 19, 2019 · 11 comments
Closed

unreachable IPs in 2.5.0 #3600

JaveriaK opened this issue Feb 19, 2019 · 11 comments
Labels
bug

Comments

@JaveriaK
Copy link

What you expected to happen?

According to kubernetes/kops#4327 (comment) I expected the issue with reclaiming IPs to be resolved. This cluster has autoscaling enabled so nodes get terminated frequently and the cluster networking layer needs to be able to handle this dynamically.
For now, I've added some automated in around the rmpeer solution so that we can recover more quickly the next time this happens.

What happened?

Noticed pods on two nodes in the cluster were having networking issues, running pods were not resolving dns to other pods and the kubernetes api.

2019/02/18 20:47:33 Healthz probe on /healthz error: Result of last exec: nslookup: can't resolve 'kubernetes.default.svc.cluster.local'
, at 2019-02-18 20:47:33.070693984 +0000 UTC, error exit status 1
2019/02/18 20:47:43 Healthz probe on /healthz error: Result of last exec: nslookup: can't resolve 'kubernetes.default.svc.cluster.local'
, at 2019-02-18 20:47:33.070693984 +0000 UTC, error exit status 1

New pods were not starting with:

Warning FailedCreatePodSandBox 112s kubelet, ip-172-31-36-15.us-west-1.compute.internal Failed create pod sandbox: rpc error: code = Unknown desc = NetworkPlugin cni failed to set up pod "pod1234-wh-23asd673" network: unable to allocate IP address: Post http://127.0.0.1:6784/ip/...: dial tcp 127.0.0.1:6784: connect: connection refused
Normal SandboxChanged 108s (x4 over 2m8s) kubelet, ip-172-31-36-15.us-west-1.compute.internal Pod sandbox changed, it will be killed and re-created.

The weave pods on these nodes were continuously restarting. I can provide full logs from these pods as well.

How to reproduce it?

This issue itself has become less frequent since the last weave upgrade to 2.5.0 (only seen thrice since)

Anything else we need to know?

kops Version 1.10.0 deployed to aws

Versions:

$ weave version: 2.5.0 / 2.5.1

$ docker version
Client:
 Version:      17.03.2-ce
 API version:  1.27
 Go version:   go1.7.5
 Git commit:   f5ec1e2
 Built:        Tue Jun 27 02:09:56 2017
 OS/Arch:      linux/amd64

Server:
 Version:      17.03.2-ce
 API version:  1.27 (minimum version 1.12)
 Go version:   go1.7.5
 Git commit:   f5ec1e2
 Built:        Tue Jun 27 02:09:56 2017
 OS/Arch:      linux/amd64
 Experimental: false

$ uname -a
Linux ip-172-31-42-248 4.4.121-k8s #1 SMP Sun Mar 11 19:39:47 UTC 2018 x86_64 GNU/Linux

$ kubectl version
Server Version: version.Info{Major:"1", Minor:"10", GitVersion:"v1.10.3", GitCommit:"2bba0127d85d5a46ab4b778548be28623b32d0b0", GitTreeState:"clean", BuildDate:"2018-05-21T09:05:37Z", GoVersion:"go1.9.3", Compiler:"gc", Platform:"linux/amd64"}

Logs:

Here a few relevant bits from the restarting/crashing weave pods (full logs from these pods can also be provided):

INFO: 2019/02/18 23:20:05.099305 overlay_switch ->[ae:2a:da:c3:28:36(ip-172-31-42-187.us-west-1.compute.internal)] using sleeve
INFO: 2019/02/18 23:20:05.102149 ->[172.31.42.187:19492|ae:2a:da:c3:28:36(ip-172-31-42-187.us-west-1.compute.internal)]: connection shutting down due to error: Inconsistent entries for 10.100.64.0: owned by f2:c1:39:11:01:d4 but incoming message says 1e:76:31:2a:3a:d1
INFO: 2019/02/18 23:35:02.335169 ->[172.31.42.208:19561|02:d0:fa:07:f7:ca(ip-172-31-42-208.us-west-1.compute.internal)]: connection shutting down due to error: cannot connect to ourself
INFO: 2019/02/18 23:35:02.335278 ->[172.31.42.208:6783|02:d0:fa:07:f7:ca(ip-172-31-42-208.us-west-1.compute.internal)]: connection shutting down due to error: cannot connect to ourself

ipam status from the time of the problem.

ae:2a:da:c3:28:36(ip-172-31-42-187.us-west-1.compute.internal)   478464 IPs (22.8% of total) (3 active)
82:d6:53:85:11:9a(ip-172-31-42-115.us-west-1.compute.internal)    65536 IPs (03.1% of total) - unreachable!
fe:d4:a1:8b:8f:e4(ip-172-31-40-20.us-west-1.compute.internal)    16384 IPs (00.8% of total) - unreachable!
16:5d:30:a4:ec:0f(ip-172-31-41-243.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
92:5c:f7:29:11:90(ip-172-31-43-95.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
4e:bb:7f:d3:ed:64(ip-172-31-41-90.us-west-1.compute.internal)    35760 IPs (01.7% of total) 
8e:77:6f:87:ba:4a(ip-172-31-42-204.us-west-1.compute.internal)    24576 IPs (01.2% of total) 
a2:d3:d2:f9:71:34(ip-172-31-40-58.us-west-1.compute.internal)    73728 IPs (03.5% of total) - unreachable!
0e:60:74:d0:6a:cc(ip-172-31-42-132.us-west-1.compute.internal)     8230 IPs (00.4% of total) 
e6:eb:cc:74:84:ed(ip-172-31-43-148.us-west-1.compute.internal)    65536 IPs (03.1% of total) - unreachable!
6a:b9:51:43:0d:56(ip-172-31-41-128.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
82:2d:3b:03:64:06(ip-172-31-41-78.us-west-1.compute.internal)    16384 IPs (00.8% of total) - unreachable!
de:00:af:a0:03:c2(ip-172-31-42-38.us-west-1.compute.internal)     8192 IPs (00.4% of total) 
02:0d:bc:15:39:ea(ip-172-31-41-167.us-west-1.compute.internal)    32819 IPs (01.6% of total) 
4e:2d:2a:6c:74:59(ip-172-31-42-84.us-west-1.compute.internal)    90112 IPs (04.3% of total) - unreachable!
1e:76:31:2a:3a:d1(ip-172-31-40-123.us-west-1.compute.internal)    16384 IPs (00.8% of total) - unreachable!
ae:fd:d9:e3:4e:87(ip-172-31-42-42.us-west-1.compute.internal)     1024 IPs (00.0% of total) - unreachable!
2e:7c:3a:6f:94:fc(ip-172-31-40-109.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
b6:49:fa:a1:fe:63(ip-172-31-40-192.us-west-1.compute.internal)    32768 IPs (01.6% of total) - unreachable!
e2:27:a1:ad:1b:b6(ip-172-31-41-20.us-west-1.compute.internal)    32768 IPs (01.6% of total) - unreachable!
92:87:7f:42:a5:ca(ip-172-31-40-235.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
02:d0:fa:07:f7:ca(ip-172-31-42-208.us-west-1.compute.internal)    65542 IPs (03.1% of total) 
9a:94:29:75:84:a4(ip-172-31-42-123.us-west-1.compute.internal)    61440 IPs (02.9% of total) - unreachable!
46:40:2a:44:eb:98(ip-172-31-41-37.us-west-1.compute.internal)    74051 IPs (03.5% of total) 
02:d0:5e:7c:ed:8c(ip-172-31-40-24.us-west-1.compute.internal)    65536 IPs (03.1% of total) 
c2:e9:07:59:15:c3(ip-172-31-43-250.us-west-1.compute.internal)    94208 IPs (04.5% of total) 
0e:c0:5e:6f:47:9b(ip-172-31-41-74.us-west-1.compute.internal)     4096 IPs (00.2% of total) - unreachable!
c2:53:83:6a:c1:1d(ip-172-31-40-163.us-west-1.compute.internal)    16384 IPs (00.8% of total) 
76:a8:b0:e1:6d:6e(ip-172-31-43-11.us-west-1.compute.internal)    16384 IPs (00.8% of total) - unreachable!
fe:a8:fb:83:83:35(ip-172-31-42-64.us-west-1.compute.internal)    16384 IPs (00.8% of total) - unreachable!
be:2e:36:ff:cc:ef(ip-172-31-43-166.us-west-1.compute.internal)    16384 IPs (00.8% of total) - unreachable!
12:53:c5:db:f1:c0(ip-172-31-43-137.us-west-1.compute.internal)   500989 IPs (23.9% of total) 
36:8d:15:d3:db:12(ip-172-31-40-25.us-west-1.compute.internal)    73778 IPs (03.5% of total) 
be:a0:09:29:1c:eb(ip-172-31-41-117.us-west-1.compute.internal)    12288 IPs (00.6% of total) - unreachable!
82:81:cd:6d:7c:f4(ip-172-31-43-32.us-west-1.compute.internal)     4096 IPs (00.2% of total) - unreachable!
4e:a9:80:b1:dd:e2(ip-172-31-41-146.us-west-1.compute.internal)    18528 IPs (00.9% of total) 
12:64:82:d0:9d:cf(ip-172-31-42-248.us-west-1.compute.internal)     1055 IPs (00.1% of total) 
7a:aa:cd:76:4d:52(ip-172-31-43-205.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
82:46:e8:98:08:51(ip-172-31-43-199.us-west-1.compute.internal)     8192 IPs (00.4% of total) - unreachable!
@murali-reddy
Copy link
Contributor

Thanks for reporting. Like you noticed 2.5 release has the fix to automate performing weave rmpeer on the the node that gets deleted by ASG. Automation does so by watching out for node delete events and performing weave rmpeer.

You should see in the logs corresponding to rmpeer activity like:

INFO: 2019/02/07 08:38:57.547465 [kube-peers] rmpeer of 7e:6a:11:d9:a8:bf: 16384 IPs taken over from 7e:6a:11:d9:a8:bf

So from the logs i have seen who reported similar issue I could not find a similar activity for peers which are listed as unreachable in ipam status. If there is failure to perform rmpeer an error is logged. I don't see any error as well. It appears that for some reason API node delete event was never sent though kubectl get nodes reflect that node is deleted. I will test out and see if I can reproduce.

@Hashfyre
Copy link

Hashfyre commented Feb 20, 2019 •
edited
Loading

Versions:

  • Kops: v1.10.0
  • Cloud Provider: AWS
  • weave: weaveworks/weave-kube:2.5.0
  • kubernetes:
    server: v1.12.1
    Client: v1.12.2
  • docker: 17.03.2-ce, build f5ec1e2

What we see

  • Weave IPAM Unreachable Percent: 52%
  • Weave IPAM Unreachable Count: 33

Weave status

/home/weave # ./weave --local status ipam

ae:38:10:75:c1:a7(ip-x-y-84-41.aws-region.compute.internal)   122880 IPs (05.9% of total) (16 active)
1a:ea:6d:bc:a9:34(ip-x-y-49-153.aws-region.compute.internal)    90112 IPs (04.3% of total)
72:82:1c:f6:ba:83(ip-x-y-94-68.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
52:c2:9e:4b:09:5d(ip-x-y-63-159.aws-region.compute.internal)    65536 IPs (03.1% of total)
b2:aa:7b:02:de:59(ip-x-y-33-22.aws-region.compute.internal)    32768 IPs (01.6% of total) - unreachable!
8a:50:e3:5a:66:01(ip-x-y-51-29.aws-region.compute.internal)    16384 IPs (00.8% of total) - unreachable!
aa:ee:05:74:b9:d4(ip-x-y-48-19.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
c2:8b:d6:dd:b0:7d(ip-x-y-112-1.aws-region.compute.internal)   184320 IPs (08.8% of total)
9e:97:c1:cc:b5:70(ip-x-y-46-29.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
86:88:8c:7d:c5:32(ip-x-y-55-244.aws-region.compute.internal)    16384 IPs (00.8% of total) - unreachable!
1e:a8:f8:61:d0:9f(ip-x-y-80-249.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
6a:73:b4:95:49:ea(ip-x-y-95-223.aws-region.compute.internal)    73728 IPs (03.5% of total)
e6:f9:7e:30:36:62(ip-x-y-60-231.aws-region.compute.internal)    32768 IPs (01.6% of total) - unreachable!
9e:91:bd:27:c3:e5(ip-x-y-86-81.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
22:fd:0e:04:e2:28(ip-x-y-120-145.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
82:01:43:66:21:36(ip-x-y-58-119.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
d2:1b:99:68:95:8e(ip-x-y-66-187.aws-region.compute.internal)    36864 IPs (01.8% of total) - unreachable!
de:26:f7:1c:d0:43(ip-x-y-39-88.aws-region.compute.internal)   163840 IPs (07.8% of total)
c6:c6:0d:fc:be:97(ip-x-y-65-6.aws-region.compute.internal)   163840 IPs (07.8% of total) - unreachable!
26:a0:88:95:d4:f7(ip-x-y-87-53.aws-region.compute.internal)    24576 IPs (01.2% of total) - unreachable!
fe:eb:5d:63:83:b6(ip-x-y-61-220.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
b2:4e:be:1b:29:25(ip-x-y-34-93.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
de:28:e5:a9:14:f4(ip-x-y-118-193.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
7a:8f:a1:63:cb:39(ip-x-y-69-228.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
ea:7c:ca:ae:64:44(ip-x-y-51-186.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
6a:df:28:22:a2:95(ip-x-y-36-124.aws-region.compute.internal)    57344 IPs (02.7% of total) - unreachable!
8e:0d:60:e7:f0:c9(ip-x-y-42-30.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
f2:9a:10:fa:f5:2c(ip-x-y-73-117.aws-region.compute.internal)    16384 IPs (00.8% of total) - unreachable!
52:a6:1a:c8:c3:1a(ip-x-y-83-128.aws-region.compute.internal)   135168 IPs (06.4% of total)
86:88:20:38:14:ef(ip-x-y-78-175.aws-region.compute.internal)   126976 IPs (06.1% of total) - unreachable!
96:ef:16:57:47:66(ip-x-y-35-94.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
7e:2c:a0:a3:6c:2e(ip-x-y-56-139.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
ae:97:cd:07:e4:5d(ip-x-y-70-207.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
f2:45:dd:00:74:bb(ip-x-y-60-10.aws-region.compute.internal)    16384 IPs (00.8% of total) - unreachable!
c6:f1:24:11:7c:0c(ip-x-y-38-50.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!
ca:a6:af:ec:59:9c(ip-x-y-59-9.aws-region.compute.internal)    73728 IPs (03.5% of total)
02:1b:07:16:9a:8b(ip-x-y-54-202.aws-region.compute.internal)   385024 IPs (18.4% of total) - unreachable!
aa:15:98:29:2f:1b(ip-x-y-76-119.aws-region.compute.internal)    16384 IPs (00.8% of total)
e6:85:87:d4:28:a9(ip-x-y-87-146.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
42:e6:6c:dd:2b:ba(ip-x-y-36-29.aws-region.compute.internal)    73728 IPs (03.5% of total)
82:8c:f5:77:b2:44(ip-x-y-77-202.aws-region.compute.internal)     8192 IPs (00.4% of total) - unreachable!
b6:7e:68:7f:06:1e(ip-x-y-35-4.aws-region.compute.internal)    40960 IPs (02.0% of total) - unreachable!
0e:a3:f8:8f:50:17(ip-x-y-48-171.aws-region.compute.internal)     4096 IPs (00.2% of total) - unreachable!

Weave Connection Status

./weave --local status connections

<- x.y.63.159:56834   established fastdp 52:c2:9e:4b:09:5d(ip-x-y-63-159.aws-region.compute.internal) mtu=8912
<- x.y.39.88:48910    established fastdp de:26:f7:1c:d0:43(ip-x-y-39-88.aws-region.compute.internal) mtu=8912
-> x.y.59.9:6783      established fastdp ca:a6:af:ec:59:9c(ip-x-y-59-9.aws-region.compute.internal) mtu=8912
-> x.y.83.128:6783    established fastdp 52:a6:1a:c8:c3:1a(ip-x-y-83-128.aws-region.compute.internal) mtu=8912
-> x.y.49.153:6783    established fastdp 1a:ea:6d:bc:a9:34(ip-x-y-49-153.aws-region.compute.internal) mtu=8912
-> x.y.112.1:6783     established fastdp c2:8b:d6:dd:b0:7d(ip-x-y-112-1.aws-region.compute.internal) mtu=8912
<- x.y.36.29:37855    established fastdp 42:e6:6c:dd:2b:ba(ip-x-y-36-29.aws-region.compute.internal) mtu=8912
<- x.y.95.223:46826   established fastdp 6a:73:b4:95:49:ea(ip-x-y-95-223.aws-region.compute.internal) mtu=8912
<- x.y.76.119:42974   established fastdp aa:15:98:29:2f:1b(ip-x-y-76-119.aws-region.compute.internal) mtu=8912
-> x.y.84.41:6783     failed      cannot connect to ourself, retry: never

Kube Nodes vs Weave Unreachable Nodes

 diff -y weave_nodes weave_unreachable_nodes
ip-x-y-112-1.aws-region.compute.internal          | ip-x-y-38-50.aws-region.compute.internal
ip-x-y-36-29.aws-region.compute.internal          | ip-x-y-87-53.aws-region.compute.internal
ip-x-y-39-88.aws-region.compute.internal          | ip-x-y-46-29.aws-region.compute.internal
ip-x-y-49-153.aws-region.compute.internal         | ip-x-y-60-231.aws-region.compute.internal
ip-x-y-59-9.aws-region.compute.internal           | ip-x-y-58-119.aws-region.compute.internal
ip-x-y-63-159.aws-region.compute.internal         | ip-x-y-42-30.aws-region.compute.internal
ip-x-y-76-119.aws-region.compute.internal         | ip-x-y-55-244.aws-region.compute.internal
ip-x-y-83-128.aws-region.compute.internal         | ip-x-y-48-171.aws-region.compute.internal
ip-x-y-84-41.aws-region.compute.internal          | ip-x-y-48-19.aws-region.compute.internal
ip-x-y-95-223.aws-region.compute.internal         | ip-x-y-87-146.aws-region.compute.internal
                                                  > ip-x-y-35-4.aws-region.compute.internal
                                                  > ip-x-y-51-29.aws-region.compute.internal
                                                  > ip-x-y-80-249.aws-region.compute.internal
                                                  > ip-x-y-69-228.aws-region.compute.internal
                                                  > ip-x-y-60-10.aws-region.compute.internal
                                                  > ip-x-y-54-202.aws-region.compute.internal
                                                  > ip-x-y-33-22.aws-region.compute.internal
                                                  > ip-x-y-61-220.aws-region.compute.internal
                                                  > ip-x-y-35-94.aws-region.compute.internal
                                                  > ip-x-y-66-187.aws-region.compute.internal
                                                  > ip-x-y-56-139.aws-region.compute.internal
                                                  > ip-x-y-65-6.aws-region.compute.internal
                                                  > ip-x-y-36-124.aws-region.compute.internal
                                                  > ip-x-y-78-175.aws-region.compute.internal
                                                  > ip-x-y-77-202.aws-region.compute.internal
                                                  > ip-x-y-94-68.aws-region.compute.internal
                                                  > ip-x-y-120-145.aws-region.compute.internal
                                                  > ip-x-y-34-93.aws-region.compute.internal
                                                  > ip-x-y-86-81.aws-region.compute.internal
                                                  > ip-x-y-118-193.aws-region.compute.internal
                                                  > ip-x-y-73-117.aws-region.compute.internal
                                                  > ip-x-y-70-207.aws-region.compute.internal
                                                  > ip-x-y-51-186.aws-region.compute.internal

Thus, we can see none of the nodes that are unreachable are currently in the cluster.
Some clarification:
This is a load testing environment where:
- Metrics scale-up pods using HPA
- Pending pod count triggers Cluster-Autoscaler
So, we see a lot for node scale-ups and eventual scale-down and terminations over the
flood test period.

Reclaim Issues

Post discussion with @murali.reddy at this point we saw that, no logs turned up for:

k8s logs -l "name=weave-net" | grep "Error while reclaiming space"
k8s logs -l "name=weave-net" | grep "Error resetting peer list"

However, we did see a bunch of rmpeer activity.

INFO: 2019/02/07 08:38:57.547465 [kube-peers] rmpeer of 7e:6a:11:d9:a8:bf: 16384 IPs taken over from 7e:6a:11:d9:a8:bf
INFO: 2019/02/07 12:15:08.567472 [kube-peers] rmpeer of 6a:ca:cd:cf:79:ec: 8192 IPs taken over from 6a:ca:cd:cf:79:ec
INFO: 2019/02/07 14:44:25.433358 [kube-peers] rmpeer of 8e:85:d1:22:69:02: 73728 IPs taken over from 8e:85:d1:22:69:02
INFO: 2019/02/15 06:40:27.827630 [kube-peers] rmpeer of b6:36:f1:73:22:3a: 8192 IPs taken over from b6:36:f1:73:22:3a
INFO: 2019/02/15 10:23:22.434404 [kube-peers] rmpeer of a2:7b:4c:6c:fa:2b: 8192 IPs taken over from a2:7b:4c:6c:fa:2b
INFO: 2019/02/15 11:04:11.022637 [kube-peers] rmpeer of 6e:f7:76:65:60:c5: 8192 IPs taken over from 6e:f7:76:65:60:c5
INFO: 2019/02/15 11:15:02.837181 [kube-peers] rmpeer of ba:71:0a:4d:02:20: 16384 IPs taken over from ba:71:0a:4d:02:20
INFO: 2019/02/06 19:27:27.515560 [kube-peers] rmpeer of c6:d5:7b:db:1d:86: 126976 IPs taken over from c6:d5:7b:db:1d:86
INFO: 2019/02/06 19:41:36.656510 [kube-peers] rmpeer of ee:16:4b:98:b1:a9: 8192 IPs taken over from ee:16:4b:98:b1:a9
INFO: 2019/02/07 11:57:20.953534 [kube-peers] rmpeer of be:ef:d3:0d:7b:40: 8192 IPs taken over from be:ef:d3:0d:7b:40
INFO: 2019/02/07 12:10:46.333387 [kube-peers] rmpeer of 96:0c:0a:24:c7:b0: 8192 IPs taken over from 96:0c:0a:24:c7:b0
INFO: 2019/02/07 12:28:23.220707 [kube-peers] rmpeer of c2:6e:e1:5b:1b:68: 24576 IPs taken over from c2:6e:e1:5b:1b:68
INFO: 2019/02/07 12:38:15.148232 [kube-peers] rmpeer of 42:c3:df:a1:9e:11: 40960 IPs taken over from 42:c3:df:a1:9e:11
INFO: 2019/02/14 06:40:37.352152 [kube-peers] rmpeer of 9e:cb:16:be:d3:ef: 16384 IPs taken over from 9e:cb:16:be:d3:ef
INFO: 2019/02/15 06:10:51.346137 [kube-peers] rmpeer of 2e:c5:35:18:f4:d8: 32768 IPs taken over from 2e:c5:35:18:f4:d8
INFO: 2019/02/15 06:10:57.168858 [kube-peers] rmpeer of 12:32:d6:d7:fd:e1: 8192 IPs taken over from 12:32:d6:d7:fd:e1
INFO: 2019/02/15 06:49:12.712616 [kube-peers] rmpeer of 0e:01:0b:dd:18:ac: 8192 IPs taken over from 0e:01:0b:dd:18:ac
INFO: 2019/02/15 11:03:54.496217 [kube-peers] rmpeer of 42:e9:bf:09:09:cf: 8192 IPs taken over from 42:e9:bf:09:09:cf
INFO: 2019/02/06 19:34:30.037732 [kube-peers] rmpeer of 1e:db:73:8a:15:75: 757760 IPs taken over from 1e:db:73:8a:15:75
INFO: 2019/02/07 08:37:31.626613 [kube-peers] rmpeer of b6:91:25:19:11:bd: 16384 IPs taken over from b6:91:25:19:11:bd
INFO: 2019/02/07 12:10:57.169734 [kube-peers] rmpeer of ea:b4:aa:37:63:5c: 16384 IPs taken over from ea:b4:aa:37:63:5c
INFO: 2019/02/07 12:36:39.397641 [kube-peers] rmpeer of 0e:bf:e0:e3:f1:91: 8192 IPs taken over from 0e:bf:e0:e3:f1:91
INFO: 2019/02/07 14:08:44.238259 [kube-peers] rmpeer of 92:95:c5:f6:68:da: 81920 IPs taken over from 92:95:c5:f6:68:da
INFO: 2019/02/14 12:25:10.279736 [kube-peers] rmpeer of ee:a8:60:59:cb:36: 16384 IPs taken over from ee:a8:60:59:cb:36
INFO: 2019/02/15 05:28:32.350703 [kube-peers] rmpeer of 96:b3:8f:37:c5:6b: 16384 IPs taken over from 96:b3:8f:37:c5:6b
INFO: 2019/02/15 10:23:38.478165 [kube-peers] rmpeer of 0a:b2:fd:30:a5:a8: 8192 IPs taken over from 0a:b2:fd:30:a5:a8
INFO: 2019/02/15 11:14:20.333073 [kube-peers] rmpeer of 76:93:21:66:7c:cf: 8192 IPs taken over from 76:93:21:66:7c:cf
INFO: 2019/02/15 06:49:26.645630 [kube-peers] rmpeer of 66:de:1e:ff:22:9d: 16384 IPs taken over from 66:de:1e:ff:22:9d
INFO: 2019/02/15 09:45:44.702565 [kube-peers] rmpeer of 56:14:d8:63:3c:ed: 16384 IPs taken over from 56:14:d8:63:3c:ed
INFO: 2019/02/15 10:10:38.952838 [kube-peers] rmpeer of 36:4c:df:21:32:23: 16384 IPs taken over from 36:4c:df:21:32:23
INFO: 2019/02/07 12:16:39.601159 [kube-peers] rmpeer of ba:5e:e3:be:d1:5d: 8192 IPs taken over from ba:5e:e3:be:d1:5d
INFO: 2019/02/14 12:00:29.452420 [kube-peers] rmpeer of 3e:ed:1f:be:7a:23: 16384 IPs taken over from 3e:ed:1f:be:7a:23
INFO: 2019/02/14 12:08:18.001303 [kube-peers] rmpeer of ca:0e:64:a9:be:bc: 16384 IPs taken over from ca:0e:64:a9:be:bc
INFO: 2019/02/14 12:08:18.024925 [kube-peers] rmpeer of 1a:8b:88:25:d3:ab: 16384 IPs taken over from 1a:8b:88:25:d3:ab
INFO: 2019/02/15 05:28:42.985869 [kube-peers] rmpeer of 06:8d:21:ef:13:28: 32768 IPs taken over from 06:8d:21:ef:13:28
INFO: 2019/02/07 12:12:16.145516 [kube-peers] rmpeer of 12:29:b9:27:6a:a7: 8192 IPs taken over from 12:29:b9:27:6a:a7
INFO: 2019/02/07 12:37:59.447538 [kube-peers] rmpeer of b2:40:6c:9c:fb:3e: 40960 IPs taken over from b2:40:6c:9c:fb:3e
INFO: 2019/02/15 06:11:33.811478 [kube-peers] rmpeer of be:00:63:28:29:53: 8192 IPs taken over from be:00:63:28:29:53
INFO: 2019/02/06 20:00:55.865812 [kube-peers] rmpeer of c6:21:82:9a:11:bf: 16384 IPs taken over from c6:21:82:9a:11:bf
INFO: 2019/02/07 12:32:08.048031 [kube-peers] rmpeer of 96:d2:7c:6c:27:86: 8192 IPs taken over from 96:d2:7c:6c:27:86
INFO: 2019/02/07 14:28:55.848126 [kube-peers] rmpeer of b2:4c:6d:fc:a9:9b: 40960 IPs taken over from b2:4c:6d:fc:a9:9b
INFO: 2019/02/14 06:54:00.617589 [kube-peers] rmpeer of c2:9a:25:40:77:ea: 16384 IPs taken over from c2:9a:25:40:77:ea
INFO: 2019/02/15 05:40:59.016466 [kube-peers] rmpeer of 6a:30:58:db:d4:f3: 32768 IPs taken over from 6a:30:58:db:d4:f3
INFO: 2019/02/15 05:40:59.038938 [kube-peers] rmpeer of 72:f6:0b:2b:bb:97: 8192 IPs taken over from 72:f6:0b:2b:bb:97
INFO: 2019/02/06 19:49:09.732016 [kube-peers] rmpeer of c2:56:b3:8e:67:ac: 8192 IPs taken over from c2:56:b3:8e:67:ac
INFO: 2019/02/07 12:12:42.618302 [kube-peers] rmpeer of ce:38:6d:0f:0c:55: 16384 IPs taken over from ce:38:6d:0f:0c:55
INFO: 2019/02/15 05:40:53.620034 [kube-peers] rmpeer of 62:f3:5e:c6:8d:b2: 16384 IPs taken over from 62:f3:5e:c6:8d:b2
INFO: 2019/02/15 05:50:01.297865 [kube-peers] rmpeer of 4e:30:16:97:c5:1c: 8192 IPs taken over from 4e:30:16:97:c5:1c
INFO: 2019/02/15 05:50:01.319847 [kube-peers] rmpeer of 32:95:bb:c2:2a:ca: 8192 IPs taken over from 32:95:bb:c2:2a:ca
INFO: 2019/02/15 06:36:15.362696 [kube-peers] rmpeer of 66:e8:35:a3:67:84: 106496 IPs taken over from 66:e8:35:a3:67:84
INFO: 2019/02/15 06:36:31.332912 [kube-peers] rmpeer of 2e:0c:f2:49:a6:fb: 8192 IPs taken over from 2e:0c:f2:49:a6:fb
INFO: 2019/02/15 10:23:28.474205 [kube-peers] rmpeer of 3e:25:9c:ee:79:28: 8192 IPs taken over from 3e:25:9c:ee:79:28
INFO: 2019/02/15 11:04:05.632234 [kube-peers] rmpeer of 4a:60:17:af:cc:07: 8192 IPs taken over from 4a:60:17:af:cc:07
INFO: 2019/02/15 11:14:46.687236 [kube-peers] rmpeer of 42:db:a2:39:25:29: 8192 IPs taken over from 42:db:a2:39:25:29
INFO: 2019/02/15 09:45:49.959194 [kube-peers] rmpeer of 8e:c8:f3:12:bc:d0: 32768 IPs taken over from 8e:c8:f3:12:bc:d0
INFO: 2019/02/15 10:09:58.924184 [kube-peers] rmpeer of 5e:5d:a4:3d:d0:cc: 32768 IPs taken over from 5e:5d:a4:3d:d0:cc

we also saw,

k8s logs -l "name=weave-net" | grep -i "registering for updates for node delete events"

DEBU: 2019/02/06 19:21:32.595950 registering for updates for node delete events
DEBU: 2019/02/06 18:56:11.589572 registering for updates for node delete events
DEBU: 2019/02/06 19:02:37.925321 registering for updates for node delete events
DEBU: 2019/02/15 06:21:56.598481 registering for updates for node delete events
DEBU: 2019/02/06 19:36:19.084219 registering for updates for node delete events
DEBU: 2019/02/06 19:43:19.497872 registering for updates for node delete events
DEBU: 2019/02/06 19:28:27.327092 registering for updates for node delete events
DEBU: 2019/02/06 19:09:31.409815 registering for updates for node delete events
DEBU: 2019/02/15 06:21:52.698691 registering for updates for node delete events

I ran a diff between Set of Unreachable Peers vs. peers listed in above IPs taken over from log

diff -y weave_unreachable weave_rmpeer_ips_take_over                                                                      

06:6e:db:2d:80:dd					      <
06:8d:21:ef:13:28						06:8d:21:ef:13:28
0a:b2:fd:30:a5:a8						0a:b2:fd:30:a5:a8
0e:01:0b:dd:18:ac						0e:01:0b:dd:18:ac
0e:bf:e0:e3:f1:91						0e:bf:e0:e3:f1:91
12:29:b9:27:6a:a7						12:29:b9:27:6a:a7
12:32:d6:d7:fd:e1						12:32:d6:d7:fd:e1
12:6b:1a:c2:6b:2a					      <
12:e4:f0:9e:2e:c0					      <
1a:8b:88:25:d3:ab						1a:8b:88:25:d3:ab
1a:cf:0b:63:7c:bc					      <
1a:e1:8f:38:c0:51					      <
1e:82:db:f6:4a:45					      <
1e:db:73:8a:15:75						1e:db:73:8a:15:75
26:02:96:fe:56:cf					      <
2e:0c:f2:49:a6:fb						2e:0c:f2:49:a6:fb
2e:18:d3:13:43:41					      <
2e:c5:35:18:f4:d8						2e:c5:35:18:f4:d8
32:95:bb:c2:2a:ca						32:95:bb:c2:2a:ca
36:4c:df:21:32:23						36:4c:df:21:32:23
3a:08:d7:3a:7a:32					      <
3e:25:9c:ee:79:28						3e:25:9c:ee:79:28
3e:45:61:c9:9c:28					      <
3e:64:3e:8e:d6:56					      <
3e:ed:1f:be:7a:23						3e:ed:1f:be:7a:23
42:9f:c3:e1:8a:86					      <
42:bf:a5:36:53:56					      <
42:c3:df:a1:9e:11						42:c3:df:a1:9e:11
42:db:a2:39:25:29						42:db:a2:39:25:29
42:e9:bf:09:09:cf						42:e9:bf:09:09:cf
46:c3:67:c1:8c:ad					      <
4a:05:c6:5c:58:9e					      <
4a:60:17:af:cc:07						4a:60:17:af:cc:07
4e:30:16:97:c5:1c						4e:30:16:97:c5:1c
56:14:d8:63:3c:ed						56:14:d8:63:3c:ed
56:f4:3f:dd:11:7f					      <
5a:f8:05:4e:5b:81					      <
5e:5d:a4:3d:d0:cc						5e:5d:a4:3d:d0:cc
62:f3:5e:c6:8d:b2						62:f3:5e:c6:8d:b2
66:de:1e:ff:22:9d						66:de:1e:ff:22:9d
66:e8:35:a3:67:84						66:e8:35:a3:67:84
6a:30:58:db:d4:f3						6a:30:58:db:d4:f3
6a:ca:cd:cf:79:ec						6a:ca:cd:cf:79:ec
6e:f7:76:65:60:c5						6e:f7:76:65:60:c5
72:f6:0b:2b:bb:97						72:f6:0b:2b:bb:97
76:93:21:66:7c:cf						76:93:21:66:7c:cf
76:c0:72:45:58:86					      <
7a:aa:29:c0:ff:d0					      <
7a:e5:ea:3f:03:07					      <
7e:6a:11:d9:a8:bf						7e:6a:11:d9:a8:bf
7e:ed:af:b1:f0:11					      <
8a:45:91:74:aa:ac					      <
8e:85:d1:22:69:02						8e:85:d1:22:69:02
8e:c8:f3:12:bc:d0						8e:c8:f3:12:bc:d0
92:95:c5:f6:68:da						92:95:c5:f6:68:da
96:0c:0a:24:c7:b0						96:0c:0a:24:c7:b0
96:b3:8f:37:c5:6b						96:b3:8f:37:c5:6b
96:d2:7c:6c:27:86						96:d2:7c:6c:27:86
9e:cb:16:be:d3:ef						9e:cb:16:be:d3:ef
a2:7b:4c:6c:fa:2b						a2:7b:4c:6c:fa:2b
a6:8e:ca:ee:19:6a					      <
b2:40:6c:9c:fb:3e						b2:40:6c:9c:fb:3e
b2:4c:6d:fc:a9:9b						b2:4c:6d:fc:a9:9b
b2:4c:e5:e6:9e:80					      <
b2:a1:b3:84:23:d2					      <
b6:36:f1:73:22:3a						b6:36:f1:73:22:3a
b6:91:25:19:11:bd						b6:91:25:19:11:bd
ba:5e:e3:be:d1:5d						ba:5e:e3:be:d1:5d
ba:71:0a:4d:02:20						ba:71:0a:4d:02:20
be:00:63:28:29:53						be:00:63:28:29:53
be:ef:d3:0d:7b:40						be:ef:d3:0d:7b:40
c2:56:b3:8e:67:ac						c2:56:b3:8e:67:ac
c2:6e:e1:5b:1b:68						c2:6e:e1:5b:1b:68
c2:9a:25:40:77:ea						c2:9a:25:40:77:ea
c6:21:82:9a:11:bf						c6:21:82:9a:11:bf
c6:6d:60:d1:ab:8e					      <
c6:d5:7b:db:1d:86						c6:d5:7b:db:1d:86
ca:0e:64:a9:be:bc						ca:0e:64:a9:be:bc
ce:38:6d:0f:0c:55						ce:38:6d:0f:0c:55
d2:18:7d:a8:52:95					      <
d2:6a:73:8d:b3:33					      <
d6:72:5f:59:5d:ef					      <
da:89:d4:2d:c6:7c					      <
da:98:b8:20:69:6b					      <
da:e9:5b:38:d7:49					      <
de:5c:0a:eb:58:8e					      <
ea:b4:aa:37:63:5c						ea:b4:aa:37:63:5c
ee:16:4b:98:b1:a9						ee:16:4b:98:b1:a9
ee:a8:60:59:cb:36						ee:a8:60:59:cb:36
fa:c8:f4:7f:23:e8					      <
fe:79:cc:8e:a2:9e					      <

We can see that,
- unreachable count = 91
- ips_taken_over_count = 56
so, all peers which are in the IPs taken over list are in the unreachable list
but, not all peers which are unreachable are in the IPs taken over list
Ips taken over is a proper subset
35 unreachable peers never had their IP ranges reclaimed

@murali-reddy
Copy link
Contributor

@JaveriaK I also see different errors. Pehaps better to follow-up as differetnt issues.

The weave pods on these nodes were continuously restarting. I can provide full logs from these pods as well.

This is unrelated to IPAM issue. Please get the kubelet logs why weave-not pod is getting restarted.

Noticed pods on two nodes in the cluster were having networking issues, running pods were not resolving dns to other pods and the kubernetes api.

Again this is a different issue. Please see if this happening on a particular node or across the cluster.

@JaveriaK
Copy link
Author

I've been watching one unreachable entry today for quite some time and looks like it hasn't managed to remove itself.

0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)    49152 IPs (02.3% of total) - unreachable!

kubectl exec -n kube-system weave-net-2hxxp -c weave -- /home/weave/weave --local status 

       Version: 2.5.1 (up to date; next check at 2019/02/21 00:15:09)
        Service: router
       Protocol: weave 1..2
           Name: 12:64:82:d0:9d:cf(ip-172-31-42-248.us-west-1.compute.internal)
     Encryption: enabled
  PeerDiscovery: enabled
        Targets: 25
    Connections: 29 (16 established, 13 failed)
          Peers: 17 (with 272 established connections)
 TrustedSubnets: none

        Service: ipam
         Status: ready
          Range: 10.96.0.0/11
  DefaultSubnet: 10.96.0.0/11

I don't see any rmpeer messages in the weave logs for this node, the only ones related to this one are:

INFO: 2019/02/20 09:09:00.595314 ->[172.31.43.103:36596|0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)]: connection shutting down due to error: read tcp4 172.31.40.24:6783->172.31.43.103:36596: read: connection reset by peer
INFO: 2019/02/20 09:09:00.595376 ->[172.31.43.103:36596|0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)]: connection deleted
INFO: 2019/02/20 09:09:00.604431 ->[172.31.43.103:6783] attempting connection
--
INFO: 2019/02/20 09:09:00.604431 ->[172.31.43.103:6783] attempting connection
INFO: 2019/02/20 09:09:00.604645 Destroying IPsec between 02:d0:5e:7c:ed:8c(ip-172-31-40-24.us-west-1.compute.internal) and 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
INFO: 2019/02/20 09:09:00.604695 ipsec: destroy: in 172.31.43.103 -> 172.31.40.24 0xb5dd46da
INFO: 2019/02/20 09:09:00.604943 ->[172.31.43.103:6783] error during connection attempt: dial tcp4 :0->172.31.43.103:6783: connect: connection refused
INFO: 2019/02/20 09:09:00.609929 ipsec: destroy: out 172.31.40.24 -> 172.31.43.103 0x9a37c699
--
--
INFO: 2019/02/20 09:09:00.604695 ipsec: destroy: in 172.31.43.103 -> 172.31.40.24 0xb5dd46da
INFO: 2019/02/20 09:09:00.604943 ->[172.31.43.103:6783] error during connection attempt: dial tcp4 :0->172.31.43.103:6783: connect: connection refused
INFO: 2019/02/20 09:09:00.609929 ipsec: destroy: out 172.31.40.24 -> 172.31.43.103 0x9a37c699
INFO: 2019/02/20 09:09:00.644291 Removed unreachable peer 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
ERRO: 2019/02/20 09:09:00.694048 Captured frame from MAC (06:6d:b8:ec:9b:48) to (0a:f7:2b:1b:11:3d) associated with another peer 02:d0:fa:07:f7:ca(ip-172-31-42-208.us-west-1.compute.internal)

ERRO: 2019/02/20 09:04:58.464726 Captured frame from MAC (56:c7:7b:7a:c2:fb) to (8e:49:90:1d:f0:81) associated with another peer 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
ERRO: 2019/02/20 09:06:37.225774 Captured frame from MAC (56:c7:7b:7a:c2:fb) to (8e:49:90:1d:f0:81) associated with another peer 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
INFO: 2019/02/20 09:08:48.376213 Discovered remote MAC 4e:9b:d3:e7:ce:64 at 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
INFO: 2019/02/20 09:08:48.770425 Discovered remote MAC aa:10:c4:e6:e2:8b at 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
INFO: 2019/02/20 09:09:00.594615 ->[172.31.43.103:37856|0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)]: connection shutting down due to error: read tcp4 172.31.42.248:6783->172.31.43.103:37856: read: connection reset by peer
INFO: 2019/02/20 09:09:00.594662 ->[172.31.43.103:37856|0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)]: connection deleted
INFO: 2019/02/20 09:09:00.601189 Destroying IPsec between 12:64:82:d0:9d:cf(ip-172-31-42-248.us-west-1.compute.internal) and 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)
INFO: 2019/02/20 09:09:00.643681 Removed unreachable peer 0a:f7:2b:1b:11:3d(ip-172-31-43-103.us-west-1.compute.internal)

@murali-reddy murali-reddy mentioned this issue Feb 25, 2019
Closed
@JaveriaK
Copy link
Author

JaveriaK commented Mar 7, 2019

This is unrelated to IPAM issue. Please get the kubelet logs why weave-not pod is getting restarted.

Noticed pods on two nodes in the cluster were having networking issues, running pods were not resolving dns to other pods and the kubernetes api.

Again this is a different issue. Please see if this happening on a particular node or across the cluster.

So I managed to debug a problematic node where weave was getting killed and turn out its being oom killed by the kernel. Here are the relevant kernel traces:

for "/system.slice/docker.service": failed to get container info for "/system.slice/docker.service": unknown container "/system.slice/docker.service"
Mar  6 05:13:56 ip-172-31-36-44 systemd[1]: Starting Run docker-healthcheck once...
Mar  6 05:13:56 ip-172-31-36-44 docker-healthcheck[76240]: docker healthy
Mar  6 05:13:56 ip-172-31-36-44 systemd[1]: Started Run docker-healthcheck once.
Mar  6 05:14:01 ip-172-31-36-44 kubelet[2336]: I0306 05:14:01.265869    2336 server.go:796] GET /metrics/cadvisor: (28.609703ms) 200 [[Prometheus/2.2.1] 172.31.31.200:53772]
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.843054] weaver invoked oom-killer: gfp_mask=0x24000c0, order=0, oom_score_adj=997
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.851340] weaver cpuset=8107e9449a59f45dba6426f30d44a01381f7de675b9df12e15b3e187c4130a19 mems_allowed=0-1
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.860462] CPU: 10 PID: 63535 Comm: weaver Tainted: G           OE   4.4.121-k8s #1
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.868549] Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.875251]  0000000000000286 1b5731cdcda683ca ffffffff812fae56 ffff881f2797be18
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.883407]  ffff883ce6ccf000 ffffffff811db28a ffff883f7da69400 ffffffff81a68560
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.891871]  0000000000000206 0000000000000001 0000000100bbbd6f ffff881f2797be18
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.900321] Call Trace:
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.903060]  [<ffffffff812fae56>] ? dump_stack+0x5c/0x86
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.908242]  [<ffffffff811db28a>] ? dump_header+0x57/0x1c1
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.912610]  [<ffffffff811715f4>] ? oom_kill_process+0x204/0x3d0
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.916808]  [<ffffffff811d371f>] ? mem_cgroup_iter+0x12f/0x350
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.921023]  [<ffffffff811d5716>] ? mem_cgroup_out_of_memory+0x296/0x300
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.925624]  [<ffffffff811d64d8>] ? mem_cgroup_oom_synchronize+0x328/0x340
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.930467]  [<ffffffff811d1b60>] ? get_mctgt_type+0x270/0x270
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.934537]  [<ffffffff81171cdd>] ? pagefault_out_of_memory+0x3d/0xb0
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.938995]  [<ffffffff815af618>] ? page_fault+0x28/0x30
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.942923] Task in /kubepods/burstable/poda1193f60-3f8e-11e9-8ff1-027603971c74/8107e9449a59f45dba6426f30d44a01381f7de675b9df12e15b3e187c4130a19 killed as a result of limit of /kubepods/burstable/poda1193f60-3f8e-11e9-8ff1-027603971c74/8107e9449a59f45dba6426f30d44a01381f7de675b9df12e15b3e187c4130a19
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.961743] memory: usage 976560kB, limit 976560kB, failcnt 139
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.965766] memory+swap: usage 0kB, limit 9007199254740988kB, failcnt 0
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.970562] kmem: usage 0kB, limit 9007199254740988kB, failcnt 0
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.974745] Memory cgroup stats for /kubepods/burstable/poda1193f60-3f8e-11e9-8ff1-027603971c74/8107e9449a59f45dba6426f30d44a01381f7de675b9df12e15b3e187c4130a19: cache:0KB rss:976560KB rss_huge:0KB mapped_file:0KB dirty:0KB writeback:0KB inactive_anon:0KB active_anon:976360KB inactive_file:0KB active_file:0KB unevictable:0KB
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49524.995308] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.001333] [63083]     0 63083      389      235       7       3        0           997 launch.sh
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.007189] [63236]     0 63236      389      160       7       3        0           997 launch.sh
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.013419] [63239]     0 63239  1547687   246134     690      11        0           997 weaver
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.019155] [63989]     0 63989      431      303       7       3        0           997 weave
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.024914] [64005]     0 64005      431       62       7       3        0           997 weave
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.030429] [64006]     0 64006     3531      818      11       3        0           997 curl
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.035935] Memory cgroup out of memory: Kill process 63239 (weaver) score 1977 or sacrifice child
Mar  6 05:14:05 ip-172-31-36-44 kernel: [49525.042250] Killed process 63239 (weaver) total-vm:6190748kB, anon-rss:960628kB, file-rss:23908kB
Mar  6 05:14:05 ip-172-31-36-44 kubelet[2336]: I0306 05:14:05.440241    2336 prober.go:111] Liveness probe for "weave-net-spl7s_kube-system(a1193f60-3f8e-11e9-8ff1-027603971c74):weave" failed (failure): Get http://127.0.0.1:6784/status: EOF
Mar  6 05:14:05 ip-172-31-36-44 kubelet[2336]: E0306 05:14:05.441726    2336 cni.go:259] Error adding network: unable to allocate IP address: Post http://127.0.0.1:6784/ip/13ed0bea8c6aa36bd17216243455c15690314b542c2e31507739a3e5d7c00958: EOF
Mar  6 05:14:05 ip-172-31-36-44 kubelet[2336]: E0306 05:14:05.441759    2336 cni.go:227] Error while adding to cni network: unable to allocate IP address: Post http://127.0.0.1:6784/ip/13ed0bea8c6aa36bd17216243455c15690314b542c2e31507739a3e5d7c00958: EOF

This one bad weave pod was also affecting the rest of the cluster and I saw all the other weave pods spike up memory usage to the limit every few minutes.

  • So firstly why would these oom kills cause the whole node to crash?
  • Secondly should we remove the memory limit to eliminate the oom kills? My concern here is that bad pods seem to take an unbounded amount as I verified through prom metrics.
  • Thirdly, since the pod seemed to be coming back with a corrupt state every time, do we need to delete weave-db state file to recover or something else in such scenarios?

also is there resource recommendations we need to follow for higher traffic clusters?

@murali-reddy
Copy link
Contributor

Mar 6 05:14:05 ip-172-31-36-44 kernel: [49524.961743] memory: usage 976560kB, limit 976560kB, failcnt 139
Mar 6 05:14:05 ip-172-31-36-44 kernel: [49525.035935] Memory cgroup out of memory: Kill process 63239 (weaver) score 1977 or sacrifice child

thanks @JaveriaK for sharing this kernel logs. As discussed in slack, there are scaling issues with large clusters, But close to 1GB usage for 70-100 node cluster seems to indicate either there is memory leaks are unbounded usage. If you run into this issue please share memory profile of weaver process. Unfortunately the one you shared is perhaps from a healthy node so not much insights I could draw.

Thirdly, since the pod seemed to be coming back with a corrupt state every time, do we need to delete weave-db state file to recover or something else in such scenarios?

Does it take time to get in to that state or is it instantly?

@murali-reddy murali-reddy added this to the 2.6 milestone Mar 12, 2019
@murali-reddy murali-reddy mentioned this issue Apr 9, 2019
Closed
@sferrett sferrett mentioned this issue Jul 12, 2019
Closed
@kostyrev
Copy link

kostyrev commented Oct 15, 2019 •
edited
Loading

I can confirm it with 2.5.2 as well
it's a single-master cluster

> k version
Server Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.10", GitCommit:"37d169313237cb4ceb2cc4bef300f2ae3053c1a2", GitTreeState:"clean", BuildDate:"2019-08-19T10:44:49Z", GoVersion:"go1.11.13", Compiler:"gc", Platform:"linux/amd64"}

-c weave -- /home/weave/weave --local status

        Version: 2.5.2 (up to date; next check at 2019/10/15 15:35:21)
        Service: router
       Protocol: weave 1..2
           Name: da:21:0e:d6:33:03(ip-10-21-56-103.ec2.internal)
     Encryption: disabled
  PeerDiscovery: enabled
        Targets: 28
    Connections: 28 (27 established, 1 failed)
          Peers: 28 (with 756 established connections)
 TrustedSubnets: none

        Service: ipam
         Status: ready
          Range: 10.32.0.0/12
  DefaultSubnet: 10.32.0.0/12

-c weave -- /home/weave/weave --local status ipam

da:21:0e:d6:33:03(ip-10-21-56-103.ec2.internal)    16384 IPs (01.6% of total) (6 active)
82:04:0f:45:34:bf(ip-10-21-88-80.ec2.internal)    12288 IPs (01.2% of total) 
32:f0:07:b8:b7:14(ip-10-21-47-9.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
3a:13:83:bf:e6:b2(ip-10-21-61-132.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
76:24:e4:8a:97:48(ip-10-21-142-51.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
6e:d1:80:6d:16:92(ip-10-21-87-221.ec2.internal)    12288 IPs (01.2% of total) 
36:d4:04:c1:b0:06(ip-10-21-41-48.ec2.internal)    12288 IPs (01.2% of total) 
5e:8a:f9:78:ab:09(ip-10-21-82-10.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
6e:c7:62:20:64:80(ip-10-21-131-108.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
d6:99:82:aa:a8:4f(ip-10-21-151-46.ec2.internal)    12288 IPs (01.2% of total) 
d2:81:76:e3:83:06(ip-10-21-84-147.ec2.internal)    12288 IPs (01.2% of total) 
c6:00:c1:ae:25:ef(ip-10-21-80-27.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
4e:aa:6d:e7:d7:75(ip-10-21-95-204.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
4a:c3:9a:fe:13:d0(ip-10-21-152-219.ec2.internal)    16384 IPs (01.6% of total) 
da:68:37:84:a6:97(ip-10-21-36-121.ec2.internal)    12288 IPs (01.2% of total) 
e6:ae:09:54:5a:66(ip-10-21-89-175.ec2.internal)    12288 IPs (01.2% of total) 
8a:0d:d2:2e:56:ce(ip-10-21-60-134.ec2.internal)    12288 IPs (01.2% of total) 
36:bb:55:d6:06:ac(ip-10-21-131-115.ec2.internal)    12288 IPs (01.2% of total) 
1a:3f:7b:e1:c9:ba(ip-10-21-39-236.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
0a:6e:00:84:1b:1f(ip-10-21-153-140.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
82:c4:a8:3b:82:bc(ip-10-21-46-43.ec2.internal)     8192 IPs (00.8% of total) - unreachable!
76:83:6e:9f:19:db(ip-10-21-141-173.ec2.internal)    20480 IPs (02.0% of total) 
e6:92:c0:f6:e7:98(ip-10-21-83-154.ec2.internal)    81920 IPs (07.8% of total) - unreachable!
fe:47:b2:11:b0:a2(ip-10-21-91-178.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
2a:ef:af:fa:98:6b(ip-10-21-53-167.ec2.internal)     8192 IPs (00.8% of total) - unreachable!
fa:7a:42:6f:6d:fe(ip-10-21-63-244.ec2.internal)    12288 IPs (01.2% of total) 
da:a8:74:bc:00:eb(ip-10-21-32-80.ec2.internal)     4096 IPs (00.4% of total) 
02:6d:d7:71:87:e7(ip-10-21-48-204.ec2.internal)    16384 IPs (01.6% of total) 
5e:94:16:ca:cc:7f(ip-10-21-86-255.ec2.internal)    16384 IPs (01.6% of total) 
ee:96:4f:35:0a:fc(ip-10-21-89-127.ec2.internal)    16384 IPs (01.6% of total) 
26:cd:c1:da:d2:e7(ip-10-21-154-63.ec2.internal)    12288 IPs (01.2% of total) 
86:d0:b5:d2:f4:f7(ip-10-21-154-182.ec2.internal)     8192 IPs (00.8% of total) 
5a:28:3d:54:95:c7(ip-10-21-36-130.ec2.internal)    12288 IPs (01.2% of total) 
ca:ac:24:f9:e4:eb(ip-10-21-143-154.ec2.internal)    24576 IPs (02.3% of total) - unreachable!
b6:72:55:5e:12:dd(ip-10-21-149-133.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
82:3e:b7:6c:71:bb(ip-10-21-76-72.ec2.internal)     8192 IPs (00.8% of total) - unreachable!
e2:39:b6:a1:f8:00(ip-10-21-46-153.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
32:d2:4d:9c:0d:76(ip-10-21-156-125.ec2.internal)    12288 IPs (01.2% of total) 
52:38:b0:5e:0d:c9(ip-10-21-85-200.ec2.internal)     8192 IPs (00.8% of total) - unreachable!
6e:1f:0c:98:ff:4d(ip-10-21-150-251.ec2.internal)    16384 IPs (01.6% of total) 
7a:8a:ca:52:73:dc(ip-10-21-89-146.ec2.internal)    12288 IPs (01.2% of total) 
9a:d2:d2:4f:24:b6(ip-10-21-34-243.ec2.internal)    12288 IPs (01.2% of total) 
46:cf:66:06:57:f6(ip-10-21-57-214.ec2.internal)    16384 IPs (01.6% of total) 
46:93:5d:5b:e4:a5(ip-10-21-61-46.ec2.internal)    24576 IPs (02.3% of total) - unreachable!
42:82:0a:84:af:81(ip-10-21-78-61.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
8e:57:5d:30:f4:4c(ip-10-21-134-124.ec2.internal)    40960 IPs (03.9% of total) - unreachable!
ca:48:87:63:79:51(ip-10-21-67-49.ec2.internal)    12288 IPs (01.2% of total) 
9a:5d:83:23:d0:83(ip-10-21-36-96.ec2.internal)    16384 IPs (01.6% of total) 
4e:19:2a:4b:05:23(ip-10-21-76-68.ec2.internal)    24576 IPs (02.3% of total) - unreachable!
0a:6f:38:70:ec:09(ip-10-21-32-63.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
6a:4a:29:12:6b:f3(ip-10-21-40-200.ec2.internal)     4096 IPs (00.4% of total) 
5e:44:63:65:bf:c2(ip-10-21-128-152.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
ca:ad:6e:90:ef:d8(ip-10-21-159-246.ec2.internal)    32768 IPs (03.1% of total) - unreachable!
da:d1:9a:1f:6d:ed(ip-10-21-74-246.ec2.internal)    16384 IPs (01.6% of total) - unreachable!
5e:09:be:b1:82:de(ip-10-21-38-131.ec2.internal)    24576 IPs (02.3% of total) - unreachable!
32:ca:b5:2f:11:f6()                       4096 IPs (00.4% of total) - unreachable!
8a:d5:8c:3b:0e:ff(ip-10-21-47-70.ec2.internal)    16384 IPs (01.6% of total) - unreachable!

 -c weave -- /home/weave/weave --local status connections

-> 10.21.63.244:6783     established fastdp fa:7a:42:6f:6d:fe(ip-10-21-63-244.ec2.internal) mtu=1376
<- 10.21.152.219:44772   established fastdp 4a:c3:9a:fe:13:d0(ip-10-21-152-219.ec2.internal) mtu=1376
-> 10.21.34.243:6783     established fastdp 9a:d2:d2:4f:24:b6(ip-10-21-34-243.ec2.internal) mtu=1376
<- 10.21.32.80:50594     established fastdp da:a8:74:bc:00:eb(ip-10-21-32-80.ec2.internal) mtu=1376
<- 10.21.86.255:42203    established fastdp 5e:94:16:ca:cc:7f(ip-10-21-86-255.ec2.internal) mtu=1376
<- 10.21.36.96:36878     established fastdp 9a:5d:83:23:d0:83(ip-10-21-36-96.ec2.internal) mtu=1376
<- 10.21.89.175:35852    established fastdp e6:ae:09:54:5a:66(ip-10-21-89-175.ec2.internal) mtu=1376
<- 10.21.67.49:44339     established fastdp ca:48:87:63:79:51(ip-10-21-67-49.ec2.internal) mtu=1376
<- 10.21.141.173:49047   established fastdp 76:83:6e:9f:19:db(ip-10-21-141-173.ec2.internal) mtu=1376
<- 10.21.60.134:34483    established fastdp 8a:0d:d2:2e:56:ce(ip-10-21-60-134.ec2.internal) mtu=1376
<- 10.21.154.63:41914    established fastdp 26:cd:c1:da:d2:e7(ip-10-21-154-63.ec2.internal) mtu=1376
<- 10.21.131.115:40009   established fastdp 36:bb:55:d6:06:ac(ip-10-21-131-115.ec2.internal) mtu=1376
<- 10.21.89.127:44876    established fastdp ee:96:4f:35:0a:fc(ip-10-21-89-127.ec2.internal) mtu=1376
<- 10.21.40.200:33104    established fastdp 6a:4a:29:12:6b:f3(ip-10-21-40-200.ec2.internal) mtu=1376
-> 10.21.150.251:6783    established fastdp 6e:1f:0c:98:ff:4d(ip-10-21-150-251.ec2.internal) mtu=1376
<- 10.21.57.214:41187    established fastdp 46:cf:66:06:57:f6(ip-10-21-57-214.ec2.internal) mtu=1376
-> 10.21.156.125:6783    established fastdp 32:d2:4d:9c:0d:76(ip-10-21-156-125.ec2.internal) mtu=1376
-> 10.21.154.182:6783    established fastdp 86:d0:b5:d2:f4:f7(ip-10-21-154-182.ec2.internal) mtu=1376
-> 10.21.87.221:6783     established fastdp 6e:d1:80:6d:16:92(ip-10-21-87-221.ec2.internal) mtu=1376
<- 10.21.151.46:35937    established fastdp d6:99:82:aa:a8:4f(ip-10-21-151-46.ec2.internal) mtu=1376
<- 10.21.36.130:55429    established fastdp 5a:28:3d:54:95:c7(ip-10-21-36-130.ec2.internal) mtu=1376
<- 10.21.36.121:45149    established fastdp da:68:37:84:a6:97(ip-10-21-36-121.ec2.internal) mtu=1376
-> 10.21.41.48:6783      established fastdp 36:d4:04:c1:b0:06(ip-10-21-41-48.ec2.internal) mtu=1376
<- 10.21.89.146:58893    established fastdp 7a:8a:ca:52:73:dc(ip-10-21-89-146.ec2.internal) mtu=1376
-> 10.21.84.147:6783     established fastdp d2:81:76:e3:83:06(ip-10-21-84-147.ec2.internal) mtu=1376
-> 10.21.88.80:6783      established fastdp 82:04:0f:45:34:bf(ip-10-21-88-80.ec2.internal) mtu=1376
<- 10.21.48.204:39095    established fastdp 02:6d:d7:71:87:e7(ip-10-21-48-204.ec2.internal) mtu=1376
-> 10.21.56.103:6783     failed      cannot connect to ourself, retry: never

klo weave-net-bkh4f -c weave | grep rmpeer

INFO: 2019/10/12 17:32:50.184685 [kube-peers] rmpeer of 2e:4d:54:36:d5:c4: 0 IPs taken over from 2e:4d:54:36:d5:c4
INFO: 2019/10/12 19:39:50.052154 [kube-peers] rmpeer of ba:8c:53:91:eb:c2: 8192 IPs taken over from ba:8c:53:91:eb:c2
INFO: 2019/10/13 19:06:04.545950 [kube-peers] rmpeer of 12:c8:69:00:29:bf: 4096 IPs taken over from 12:c8:69:00:29:bf
INFO: 2019/10/14 19:38:22.504450 [kube-peers] rmpeer of c6:85:d8:04:dd:56: 4096 IPs taken over from c6:85:d8:04:dd:56

> kex weave-net-bkh4f -c weave date
Tue Oct 15 15:37:03 UTC 2019

DEBU: 2019/10/15 14:04:31.283098 [kube-peers] Nodes that have disappeared: map[]
DEBU: 2019/10/15 14:04:43.706827 [kube-peers] Nodes that have disappeared: map[]
DEBU: 2019/10/15 14:35:38.197632 [kube-peers] Nodes that have disappeared: map[]

@bboreham
Copy link
Contributor

@kostyrev Do you have older logs? It would be interesting to see the log where it should do rmpeer, but for one of the nodes that turns up as "unreachable"

What you are showing is further evidence that something went wrong, but nothing we can use to track down the problem directly.

@kostyrev
Copy link

kostyrev commented Oct 15, 2019 •
edited
Loading

I've got logs starting from 2019/10/12 but there are no mentions of unreachable nodes.
Here's the link
thanks

@bboreham
Copy link
Contributor

That appears to be 33 minutes older, and not covering the period when any of those nodes disappeared.

@bboreham bboreham removed this from the 2.6 milestone Dec 13, 2019
@bboreham
Copy link
Contributor

Release 2.6 fixed a lot of things that would cause symptoms described here.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@Hashfyre @murali-reddy @kostyrev @JaveriaK @bboreham