weave-net hangs - leaking IP addresses?

[mikebryant]

What you expected to happen?

/status etc to work

What happened?

/status (and all other endpoints) hang

Issuance of IP addresses to pods also seemed to stop on the affected nodes

How to reproduce it?

Unknown. Happened on multiple nodes in our cluster

Anything else we need to know?

Versions:

$ weave --local version
weave 2.5.0
$ docker version
$ uname -a
Linux kubernetes-kubernetes-cr0-17-1547767704 4.14.67-coreos #1 SMP Mon Sep 10 23:14:26 UTC 2018 x86_64 Linux
$ kubectl version
Client Version: version.Info{Major:"1", Minor:"9", GitVersion:"v1.9.10", GitCommit:"098570796b32895c38a9a1c9286425fb1ececa18", GitTreeState:"clean", BuildDate:"2018-08-02T17:19:54Z", GoVersion:"go1.9.3", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"9", GitVersion:"v1.9.10", GitCommit:"098570796b32895c38a9a1c9286425fb1ececa18", GitTreeState:"clean", BuildDate:"2018-08-02T17:11:51Z", GoVersion:"go1.9.3", Compiler:"gc", Platform:"linux/amd64"}

Logs:

or, if using Kubernetes:

$ kubectl logs -n kube-system <weave-net-pod> weave

(After triggering a kill -ABRT)

weave-logs-1548156065-weave-net-4mdf6.txt

Network:

$ ip route
$ ip -4 -o addr
$ sudo iptables-save

[bboreham]

You should get a stack trace in the logs upon sending SIGQUIT

[mikebryant]

@bboreham Sorry, just reformatted my original comment - the link was inside the code block.

There's a goroutine dump in that log file, from SIGABRT. Is that the same thing? Or would SIGQUIT give different results?

[mikebryant]

weave-sigquit.txt

[bboreham]

Yeah, basically the same thing but if our code is in control then we get a timestamp of the stack dump.
Plus it won't actually quit the program, just dump goroutines and carry on.

The status call is hung here:

goroutine 247798 [chan send, 1037 minutes]:
github.com/weaveworks/weave/ipam.NewStatus(0xc4213e1340, 0xc4ac1f0000, 0x11, 0xc4271921c0)
    /go/src/github.com/weaveworks/weave/ipam/status.go:51 +0xfa
main.HandleHTTP.func1(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /go/src/github.com/weaveworks/weave/prog/weaver/http.go:314 +0x10d
main.HandleHTTP.func4.1(0x1a77ba0, 0xc425562000, 0xc426f8e200)
    /go/src/github.com/weaveworks/weave/prog/weaver/http.go:359 +0x47

which in turn is blocked on the Allocator actor loop:

goroutine 178 [IO wait, 1046 minutes]:
internal/poll.runtime_pollWait(0x7f3ecc3c8680, 0x77, 0xc422431788)
    /usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc421d34f98, 0x77, 0xffffffffffffff00, 0x1a5ea80, 0x277e3f8)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitWrite(0xc421d34f98, 0xc4200c1900, 0x74, 0x74)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:94 +0x3d
internal/poll.(*FD).Write(0xc421d34f80, 0xc4200c1980, 0x74, 0x74, 0x0, 0x0, 0x0)
    /usr/local/go/src/internal/poll/fd_unix.go:264 +0x237
net.(*netFD).Write(0xc421d34f80, 0xc4200c1980, 0x74, 0x74, 0xc4224318b0, 0x442787, 0x80)
    /usr/local/go/src/net/fd_unix.go:220 +0x4f
net.(*conn).Write(0xc421d387a0, 0xc4200c1980, 0x74, 0x74, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/net.go:188 +0x6a
github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh.(*lengthPrefixTCPSender).Send(0xc4225a21b0, 0xc4214949a0, 0x70, 0x70, 0x60, 0x60)
    /go/src/github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh/protocol_crypto.go:110 +0xfa
github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh.(*encryptedTCPSender).Send(0xc4224ab230, 0xc422d49b00, 0x60, 0x60, 0x0, 0x0)
    /go/src/github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh/protocol_crypto.go:131 +0x130
github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh.(*LocalConnection).sendProtocolMsg(0xc421d47ce0, 0xc422431a05, 0xc421b1b980, 0x5f, 0xbb, 0xc421753c00, 0x1a5c540)
    /go/src/github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh/connection.go:424 +0xc1
github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh.(*LocalConnection).SendProtocolMsg(0xc421d47ce0, 0x1a80a05, 0xc421b1b980, 0x5f, 0xbb, 0xc4244ca460, 0x158f880)
    /go/src/github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh/connection.go:130 +0x56
github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh.(*gossipChannel).relayUnicast(0xc421ac7600, 0xea617f6d0fae, 0xc421b1b980, 0x5f, 0xbb, 0xbb, 0xc422431ba0)
    /go/src/github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh/gossip_channel.go:102 +0xe1
github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh.(*gossipChannel).GossipUnicast(0xc421ac7600, 0xea617f6d0fae, 0xc423684100, 0x37, 0x40, 0xc423684100, 0x1)
    /go/src/github.com/weaveworks/weave/vendor/github.com/weaveworks/mesh/gossip_channel.go:77 +0x1ac
github.com/weaveworks/weave/ipam.(*Allocator).sendSpaceRequest(0xc4213e1340, 0xea617f6d0fae, 0xac1f8000ac1f0000, 0x2, 0x2)
    /go/src/github.com/weaveworks/weave/ipam/allocator.go:804 +0x101
github.com/weaveworks/weave/ipam.(*allocate).Try(0xc4241165c0, 0xc4213e1340, 0xc422431f00)
    /go/src/github.com/weaveworks/weave/ipam/allocate.go:59 +0x451
github.com/weaveworks/weave/ipam.(*Allocator).tryOps(0xc4213e1340, 0xc4213e13c8)
    /go/src/github.com/weaveworks/weave/ipam/allocator.go:253 +0x72
github.com/weaveworks/weave/ipam.(*Allocator).tryPendingOps(0xc4213e1340)
    /go/src/github.com/weaveworks/weave/ipam/allocator.go:267 +0x6d
github.com/weaveworks/weave/ipam.(*Allocator).actorLoop(0xc4213e1340, 0xc4219bd380, 0xc42144d680)

which is blocked sending some data.

It's not immediately clear to me why that is. I don't recall changing anything in that area recently.

[mikebryant]

Not sure if it's related, but we also seem to be having weird issues with weave using up the entire IP space..

/home/weave # ./weave --local status ipam
86:72:9b:9f:43:84(kubernetes-vectorprd-kubernetes-cr0-4-1542712907)      904 IPs (02.8% of total) (904 active)

[mikebryant]

(Though it's hard to see, when weave keeps hanging and making the status inaccessible)

[bboreham]

Is it implied that you don't expect 904 active pods on that node?

[mikebryant]

Sorry, yes - we're running with the default 110 pods per node hard limit

[mikebryant]

That node happens to have 24 pods in the kubernetes API, with 7 of those being hostNetwork daemonsets which shouldn't consume an IP

Not sure what's happened to weave to leave it so confused

[bboreham]

That prompted me to go look at the code for PruneOwned() which removes dead containers after a restart, but that relies on talking to Docker so it won't get run in a Kubernetes deployment.

Generally we do see kubelet call CNI to remove pods on restart, even dead ones.

I wonder if, given crashes, restarts, etc., Weave Net can get more and more out of sync over time.

[mikebryant]

We do have an annoyingly high amount of issues with docker - and our response is normally to reboot the node. The weave database will survive this, but docker's list of containers vanishes..

[mikebryant]

So hmm, a theory - in the event that every node in the cluster believes all IP addresses in use, is it possible that the IP allocator is blocked inside a lock, leading all status calls to fail?

(And maybe that's why we see the pods fail some time after starting - the first time a new container is scheduled to it and it's unable to give it an IP triggers this behaviour?)

[bboreham]

If a node is out of space it should immediately deny the request for more space. I guess it's possible that one is blocked on another, and perhaps in a chain back to the first one. Seems unlikely.

Maybe run with --log-level=debug to try to extract more info?

Given the described state of this cluster I would probably go round deleting the Weave Net persistence file and restarting (or rebooting). weaver should pick up the actual in-use addresses on the node and pick up the overall cluster ownership from neighbour nodes.

[mikebryant]

We've been wiping out the persistence files and rebooting (and doing a few of those nodes has stopped the hanging from happening).. Don't think we can reproduce it on that cluster, at least for a while.

I'll see if I can get a smaller test-case going. And this is likely to reoccur in time in production. Can get more debug logs next time

[mikebryant]

The leaking IP addresses is continuing. We're leaking around 300 per day.

[mikebryant]

Is there any way to peek inside weave and find out what IP addresses / IDs they correspond to? The API (as far as I can tell) only gives us the ranges assigned to each node.

I also can't see any way to mitigate this by looking at the real state of which IP addresses are used and remove them from weave - is there an API call for that?

[bboreham]

curl 127.0.0.1:6784/ip to see what is "owned"

Send an http DELETE to remove one. See weave detach in the weave shell script for example.

[mikebryant]

That's really useful, thanks for the pointer :)

[bboreham]

I imagine the way forward is to write a version of PruneOwned that works more like weave ps for the case where we don't talk to Docker (including the weave-kube case).

Maybe there is a corner case where the namespace doesn't exist and/or IP isn't assigned to a namespace now, but it will be shortly?

[mikebryant]

For info, we've ended up writing and deploying this: https://github.com/ocadotechnology/weave-wiper

[murali-reddy]

Generally we do see kubelet call CNI to remove pods on restart, even dead ones.
I wonder if, given crashes, restarts, etc., Weave Net can get more and more out of sync over time.

I am able to easily reproduce the leaking IP scenario

So I do kubectl delete pods weave-net-bkxln -n kube-system; kubectl delete pods frontend-69859f6796-nq8d6 for the pods running on the same node.

kubelet and CNI interaction fails as expected

May 01 10:13:47 weave-node2 kubelet[1674]: weave-cni: error removing interface "eth0": Link not found
May 01 10:13:47 weave-node2 kubelet[1674]: weave-cni: unable to release IP address: Delete http://127.0.0.1:6784/ip/8bc16eac402e41046ab40817a4ebd4aa00156824a6156b0c6c5d33b5d3389abb: dial tcp 127.0.0.1:6784: connect: connection refused
May 01 10:13:47 weave-node2 kubelet[1674]: E0501 10:13:47.465731    1674 remote_runtime.go:109] RunPodSandbox from runtime service failed: rpc error: code = Unknown desc = failed to set up sandbox container "8bc16eac402e41046ab40817a4ebd4aa00156824a6156b0c6c5d33b5d3389abb" network 
May 01 10:13:47 weave-node2 kubelet[1674]: E0501 10:13:47.465764    1674 kuberuntime_sandbox.go:68] CreatePodSandbox for pod "frontend-69859f6796-ps54z_default(b44a7622-6bcb-11e9-ab4a-08002737ffe1)" failed: rpc error: code = Unknown desc = failed to set up sandbox container "8bc16e
May 01 10:13:47 weave-node2 kubelet[1674]: E0501 10:13:47.465781    1674 kuberuntime_manager.go:693] createPodSandbox for pod "frontend-69859f6796-ps54z_default(b44a7622-6bcb-11e9-ab4a-08002737ffe1)" failed: rpc error: code = Unknown desc = failed to set up sandbox container "8bc16
May 01 10:13:47 weave-node2 kubelet[1674]: E0501 10:13:47.465819    1674 pod_workers.go:190] Error syncing pod b44a7622-6bcb-11e9-ab4a-08002737ffe1 ("frontend-69859f6796-ps54z_default(b44a7622-6bcb-11e9-ab4a-08002737ffe1)"), skipping: failed to "CreatePodSandbox" for "frontend-6985
May 01 10:13:47 weave-node2 kubelet[1674]: E0501 10:13:47.716332    1674 kubelet_pods.go:1093] Failed killing the pod "frontend-69859f6796-nq8d6": failed to "KillContainer" for "php-redis" with KillContainerError: "rpc error: code = Unknown desc = Error: No such container: 835adc9c
May 01 10:13:48 weave-node2 kubelet[1674]: W0501 10:13:48.210269    1674 cni.go:309] CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "8bc16eac402e41046ab40817a4ebd4aa00156824a6156b0c6c5d33b5d3389abb"
May 01 10:13:48 weave-node2 kubelet[1674]: weave-cni: unable to release IP address: 400 Bad Request: Delete: no addresses for 8bc16eac402e41046ab40817a4ebd4aa00156824a6156b0c6c5d33b5d3389abb

there is no external attempt (from kubelet) to retry CNI DEL command leaking the IP.

So weave-net pod has crashed or is unresponsive then IP's are leaked if the pods are deleted.

[murali-reddy]

write a version of PruneOwned that works more like weave ps for the case where we don't talk to Docker (including the weave-kube case).

@bboreham weave ps uses weaveutil which still uses docker https://github.com/weaveworks/weave/blob/v2.5.1/prog/weaveutil/addrs.go#L17

Does it make sense to add PruneOwned functionality for Kubernete in kube-utils similar to reclaim?

[bboreham]

Ah, good point. I misremembered how that worked.

No, I don't want to base it solely on Kubernetes info; that will miss any non-Kubernetes Docker containers that are running on the machine.

Can we just iterate every network namespace (possibly every process?) and find the in-use addresses that way? There's code here: https://github.com/weaveworks/scope/blob/master/probe/docker/network_linux.go#L19 to go from a pid.

[bboreham]

there is no external attempt (from kubelet) to retry CNI DEL command leaking the IP.

We could do some retrying inside the Weave CNI plugin, if we get a problem that could be transient (i.e. not a 200 or 400 response).

[murali-reddy]

Can we just iterate every network namespace (possibly every process?) and find the in-use addresses that way?

Make sense, it will be more generic and reliable way. Will give it a try.

[bboreham]

I remembered a bit more of the history about this: we explicitly return success when the daemon doesn't exist because of https://github.com/kubernetes/kubernetes/issues/44307, but that issue was fixed a couple of years ago so we could go back to returning an error, and then kubelet would retry.

[murali-reddy]

Yes, that worked. If i return the error from the CNI, then kubelet retry would fix the leak. It does seem kubelet is stateful, even if i restart the kublet, it does re-attempt to CNI DEL. It seems we could rely on kubelet instead of implementing PruneOwned that works for non docker.

[kasim457]

@mikebryant , could you help us how to use weave-wiper script in kubernetes cluster.

[bboreham]

Closed by 3638