search

weaveworks / weave

Simple, resilient multi-host containers networking and more.
https://www.weave.works
Apache License 2.0
6.61k stars 665 forks source link

weave not deleting network interfaces #3406

Open MikeMichel opened 5 years ago

MikeMichel commented 5 years ago

What you expected to happen?

weave removes network interface after containers are stopped

What happened?

A lot of interfaces stay forever until the hard limit of 1024 is reached and no more containers can be started docker: Error response from daemon: attaching veth "vethwepl23795" to "weave": exchange full.

How to reproduce it?

We have hundreds of container starts on our DC/OS cluster. Hard to say why/when it happens.

$ weave version 2.4.0
$ docker version 1.11.2
$ uname -a CentOS Linux release 7.4.1708 3.10.0-514.26.2.el7.x86_64

Logs:

$ docker logs weave
WARN: 2018/09/20 11:07:31.624781 Error intercepting response: attaching veth "vethwepl23795" to "weave": exchange full

We used weave 1.8.0 before and never saw this problem.

murali-reddy commented 5 years ago

As you reported this error is result of reaching hard limit of 1024 bridge ports (as noted in https://github.com/weaveworks/weave/issues/3258 as well). But we need to find the interfaces for deleted containers were not cleaned up. Could you please share or check in the logs if there was attempt to delete the interface or failure to delete the interfaces of the containers?

brb commented 5 years ago

@MikeMichel

Noting that you run Docker 1.11.2 which can leak netns preventing from removing the ifaces (https://github.com/moby/moby/issues/32090).

MikeMichel commented 5 years ago

I just created a 4 node weave 2.4.0 cluster with docker 18.06.0-ce (no mesos etc.) 

[root@node1 ~]# cat /etc/systemd/system/weave.service
[Unit]
Description=Weave Network
Documentation=http://docs.weave.works/weave/latest_release/
Requires=docker.service
After=docker.service

[Service]
EnvironmentFile=-/etc/sysconfig/weave
# weave 1.8.0
# ExecStartPre=/usr/local/bin/weave launch-router --name ::10 --no-restart --dns-domain="node.intern." --ipalloc-range 10.0.0.0/8 --ipalloc-default-subnet 10.1.1.0/24 --password hjoo7VourohpeiChiepai8piakohdoh811princE $PEERS

ExecStartPre=/usr/local/bin/weave launch --log-level=debug --name ::1 --no-restart --dns-domain="node.intern." --ipalloc-range 10.0.0.0/8 --ipalloc-default-subnet 10.1.1.0/24 --password hjoo7VourohpeiChiepai8piakohdoh811princE --rewrite-inspect -H unix:///var/run/weave/weave.sock --no-default-ipalloc --ipalloc-init seed=::1,::2,::3 $PEERS
ExecStart=/usr/bin/docker attach weave
ExecStop=/usr/local/bin/weave stop
Restart=always

[Install]
WantedBy=multi-user.target

[root@node1 ~]# cat /etc/sysconfig/weave
PEERS="20.20.20.21 20.20.20.22 20.20.20.23"
SEED="::1,::2,::3"
WEAVE_NO_FASTDP=true
WEAVE_MTU=1414
[root@node1 ~]# ip a|grep vethwepl|wc -l && docker ps|grep /w/w|wc -l
0
0
[root@node1 ~]# docker ps
CONTAINER ID        IMAGE                    COMMAND                  CREATED             STATUS              PORTS               NAMES
8be3b036baa9        weaveworks/weave:2.4.0   "/home/weave/weaver …"   28 minutes ago      Up 28 minutes                           weave
[root@node1 ~]# weave status

        Version: 2.4.0 (version 2.4.1 available - please upgrade!)

        Service: router
       Protocol: weave 1..2
           Name: 00:00:00:00:00:01(node1)
     Encryption: enabled
  PeerDiscovery: enabled
        Targets: 3
    Connections: 4 (3 established, 1 failed)
          Peers: 4 (with 12 established connections)
 TrustedSubnets: none

        Service: ipam
         Status: ready
          Range: 10.0.0.0/8
  DefaultSubnet: 10.1.1.0/24

        Service: dns
         Domain: node.intern.
       Upstream: 10.0.2.3
            TTL: 1
        Entries: 0

        Service: proxy
        Address: unix:///var/run/weave/weave.sock

        Service: plugin (legacy)
     DriverName: weave

[root@node1 ~]# ip a|grep vethwepl|wc -l && docker ps|grep /w/w|wc -l
0
0
[root@node1 ~]# docker -H unix:///var/run/weave/weave.sock run -d -e WEAVE_CIDR=net:10.1.0.0/24 nginx
0052144510f6c01e1cff8661d881d24cedcc0f016153fc5a2d34f3f0ac92f4cb
[root@node1 ~]# docker -H unix:///var/run/weave/weave.sock run -d -e WEAVE_CIDR=net:10.1.0.0/24 nginx
735490795cf2b54c077001ee14a1582a7b93feead908c76b79b1f0f575b1d7d2
[root@node1 ~]# docker -H unix:///var/run/weave/weave.sock run -d -e WEAVE_CIDR=net:10.1.0.0/24 nginx
eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242
[root@node1 ~]# docker -H unix:///var/run/weave/weave.sock run -d -e WEAVE_CIDR=net:10.1.0.0/24 nginx
885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516
[root@node1 ~]# ip a|grep vethwepl|wc -l && docker ps|grep /w/w|wc -l
4
4
[root@node1 ~]# docker -H unix:///var/run/weave/weave.sock stop 005214 735490 eeb57f 885125
005214
735490
eeb57f
885125
[root@node1 ~]# ip a|grep vethwepl|wc -l && docker ps|grep /w/w|wc -l
4
0
[root@node1 ~]# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 52:54:00:c9:c7:04 brd ff:ff:ff:ff:ff:ff
    inet 10.0.2.15/24 brd 10.0.2.255 scope global noprefixroute dynamic eth0
       valid_lft 83864sec preferred_lft 83864sec
    inet6 fe80::5054:ff:fec9:c704/64 scope link
       valid_lft forever preferred_lft forever
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether 08:00:27:a2:e9:5a brd ff:ff:ff:ff:ff:ff
    inet 20.20.20.21/24 brd 20.20.20.255 scope global noprefixroute eth1
       valid_lft forever preferred_lft forever
    inet6 fe80::a00:27ff:fea2:e95a/64 scope link
       valid_lft forever preferred_lft forever
4: docker0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN group default
    link/ether 02:42:50:3d:8c:96 brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.1/16 brd 172.17.255.255 scope global docker0
       valid_lft forever preferred_lft forever
    inet6 fe80::42:50ff:fe3d:8c96/64 scope link
       valid_lft forever preferred_lft forever
5: weave: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue state UP group default qlen 1000
    link/ether 00:00:00:00:00:01 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::200:ff:fe00:1/64 scope link
       valid_lft forever preferred_lft forever
6: dummy0: <BROADCAST,NOARP> mtu 1500 qdisc noop state DOWN group default qlen 1000
    link/ether fa:5e:c3:74:e2:74 brd ff:ff:ff:ff:ff:ff
8: vethwe-pcap@vethwe-bridge: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue state UP group default
    link/ether ba:07:40:a0:39:e1 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::b807:40ff:fea0:39e1/64 scope link
       valid_lft forever preferred_lft forever
9: vethwe-bridge@vethwe-pcap: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue master weave state UP group default
    link/ether ae:a7:8e:b9:3f:cd brd ff:ff:ff:ff:ff:ff
    inet6 fe80::aca7:8eff:feb9:3fcd/64 scope link
       valid_lft forever preferred_lft forever
69: vethwepl6919@if68: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue master weave state UP group default
    link/ether ca:53:a3:98:8a:02 brd ff:ff:ff:ff:ff:ff link-netnsid 14
    inet6 fe80::c853:a3ff:fe98:8a02/64 scope link
       valid_lft forever preferred_lft forever
73: vethwepl7064@if72: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue master weave state UP group default
    link/ether 9e:74:4a:63:0d:b4 brd ff:ff:ff:ff:ff:ff link-netnsid 15
    inet6 fe80::9c74:4aff:fe63:db4/64 scope link
       valid_lft forever preferred_lft forever
77: vethwepl7212@if76: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue master weave state UP group default
    link/ether ca:29:93:87:37:6d brd ff:ff:ff:ff:ff:ff link-netnsid 16
    inet6 fe80::c829:93ff:fe87:376d/64 scope link
       valid_lft forever preferred_lft forever
81: vethwepl7359@if80: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1414 qdisc noqueue master weave state UP group default
    link/ether ca:a1:a6:4e:e3:c8 brd ff:ff:ff:ff:ff:ff link-netnsid 17
    inet6 fe80::c8a1:a6ff:fe4e:e3c8/64 scope link
       valid_lft forever preferred_lft forever

Logs:

INFO: 2018/10/16 18:03:13.002447 Creating container with WEAVE_CIDR "net:10.1.0.0/24"
DEBU: 2018/10/16 18:03:13.011589 <-requestBody: {"AttachStderr":false,"AttachStdin":false,"AttachStdout":false,"Cmd":["nginx","-g","daemon off;"],"Domainname":"","Entrypoint":["/w/w"],"Env":["WEAVE_CIDR=net:10.1.0.0/24"],"HostConfig":{"AutoRemove":false,"Binds":["/var/lib/docker/volumes/b4b8c62d481a78558cb938cbfe913c1fced0316a2d72862bdef39aa10600efc2/_data:/w:ro"],"BlkioDeviceReadBps":null,"BlkioDeviceReadIOps":null,"BlkioDeviceWriteBps":null,"BlkioDeviceWriteIOps":null,"BlkioWeight":0,"BlkioWeightDevice":[],"CapAdd":null,"CapDrop":null,"Cgroup":"","CgroupParent":"","ConsoleSize":[0,0],"ContainerIDFile":"","CpuCount":0,"CpuPercent":0,"CpuPeriod":0,"CpuQuota":0,"CpuRealtimePeriod":0,"CpuRealtimeRuntime":0,"CpuShares":0,"CpusetCpus":"","CpusetMems":"","DeviceCgroupRules":null,"Devices":[],"DiskQuota":0,"Dns":["172.17.0.1"],"DnsOptions":[],"DnsSearch":["node.intern."],"ExtraHosts":null,"GroupAdd":null,"IOMaximumBandwidth":0,"IOMaximumIOps":0,"IpcMode":"","Isolation":"","KernelMemory":0,"Links":null,"LogConfig":{"Config":{},"Type":""},"MaskedPaths":null,"Memory":0,"MemoryReservation":0,"MemorySwap":0,"MemorySwappiness":-1,"NanoCpus":0,"NetworkMode":"default","OomKillDisable":false,"OomScoreAdj":0,"PidMode":"","PidsLimit":0,"PortBindings":{},"Privileged":false,"PublishAllPorts":false,"ReadonlyPaths":null,"ReadonlyRootfs":false,"RestartPolicy":{"MaximumRetryCount":0,"Name":"no"},"SecurityOpt":null,"ShmSize":0,"UTSMode":"","Ulimits":null,"UsernsMode":"","VolumeDriver":"","VolumesFrom":null},"Hostname":"","Image":"nginx","Labels":{},"NetworkingConfig":{"EndpointsConfig":{}},"OnBuild":null,"OpenStdin":false,"StdinOnce":false,"Tty":false,"User":"","Volumes":{},"WorkingDir":""}
DEBU: 2018/10/16 18:03:13.049494 Response from target: 201 Created map[Content-Length:[90] Api-Version:[1.38] Content-Type:[application/json] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:03:13 GMT]]
INFO: 2018/10/16 18:03:13.051457 POST /v1.38/containers/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242/wait?condition=next-exit
DEBU: 2018/10/16 18:03:13.055089 Response from target: 200 OK map[Date:[Tue, 16 Oct 2018 18:03:13 GMT] Api-Version:[1.38] Content-Type:[application/json] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)]]
INFO: 2018/10/16 18:03:13.056012 POST /v1.38/containers/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242/start
DEBU: 2018/10/16 18:03:13.554636 Wait for start of container eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242
DEBU: 2018/10/16 18:03:13.559301 [net] ContainerStarted: eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242
INFO: 2018/10/16 18:03:13.565023 Attaching container eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242 with WEAVE_CIDR "net:10.1.0.0/24" to weave network
DEBU: 2018/10/16 18:03:13.565070 weave POST to http://127.0.0.1:6784/ip/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242/10.1.0.0/24 with map[check-alive:[true]]
DEBU: 2018/10/16 18:03:13.567793 [http] POST /ip/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242/10.1.0.0/24
DEBU: 2018/10/16 18:03:13.571472 [net] ContainerStarted: eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242
DEBU: 2018/10/16 18:03:13.576687 [allocator 00:00:00:00:00:01]: Allocated 10.1.0.3 for eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242 in 10.1.0.0/24
DEBU: 2018/10/16 18:03:13.580948 Running image "weaveworks/weaveexec:2.4.0"; entrypoint=["sh"]; cmd="[-c echo '# created by Weave - BEGIN\n# container hostname\n10.1.0.3        ee]"; binds=["/var/lib/docker/containers/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242:/container"]
DEBU: 2018/10/16 18:03:14.261549 [net] ContainerStarted: 070074e2ef1943d5d0cd523d6165c54df64ed2b9964345081862b1ed2f7a5720
DEBU: 2018/10/16 18:03:14.263819 [net] ContainerStarted: 070074e2ef1943d5d0cd523d6165c54df64ed2b9964345081862b1ed2f7a5720
DEBU: 2018/10/16 18:03:14.323415 weave PUT to http://127.0.0.1:6784/name/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242/10.1.0.3 with map[fqdn:[eeb57f6f00e4.]]
DEBU: 2018/10/16 18:03:14.323690 Discovered local MAC 22:2e:bd:d1:f7:63
DEBU: 2018/10/16 18:03:14.323800 [http] PUT /name/eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242/10.1.0.3
INFO: 2018/10/16 18:03:14.323924 [nameserver 00:00:00:00:00:01] Ignoring registration eeb57f6f00e4. 10.1.0.3 eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242 (not a subdomain of node.intern.)
DEBU: 2018/10/16 18:03:14.324077 Response from target: 204 No Content map[Date:[Tue, 16 Oct 2018 18:03:13 GMT] Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)]]
DEBU: 2018/10/16 18:03:15.333765 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:03:15.351674 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
INFO: 2018/10/16 18:03:15.376523 GET /_ping
DEBU: 2018/10/16 18:03:15.378471 Response from target: 200 OK map[Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:03:15 GMT] Content-Length:[2] Content-Type:[text/plain; charset=utf-8]]
INFO: 2018/10/16 18:03:15.381701 POST /v1.38/containers/create
DEBU: 2018/10/16 18:03:15.381776 ->requestBody: {"Hostname":"","Domainname":"","User":"","AttachStdin":false,"AttachStdout":false,"AttachStderr":false,"Tty":false,"OpenStdin":false,"StdinOnce":false,"Env":["WEAVE_CIDR=net:10.1.0.0/24"],"Cmd":null,"Image":"nginx","Volumes":{},"WorkingDir":"","Entrypoint":null,"OnBuild":null,"Labels":{},"HostConfig":{"Binds":null,"ContainerIDFile":"","LogConfig":{"Type":"","Config":{}},"NetworkMode":"default","PortBindings":{},"RestartPolicy":{"Name":"no","MaximumRetryCount":0},"AutoRemove":false,"VolumeDriver":"","VolumesFrom":null,"CapAdd":null,"CapDrop":null,"Dns":[],"DnsOptions":[],"DnsSearch":[],"ExtraHosts":null,"GroupAdd":null,"IpcMode":"","Cgroup":"","Links":null,"OomScoreAdj":0,"PidMode":"","Privileged":false,"PublishAllPorts":false,"ReadonlyRootfs":false,"SecurityOpt":null,"UTSMode":"","UsernsMode":"","ShmSize":0,"ConsoleSize":[0,0],"Isolation":"","CpuShares":0,"Memory":0,"NanoCpus":0,"CgroupParent":"","BlkioWeight":0,"BlkioWeightDevice":[],"BlkioDeviceReadBps":null,"BlkioDeviceWriteBps":null,"BlkioDeviceReadIOps":null,"BlkioDeviceWriteIOps":null,"CpuPeriod":0,"CpuQuota":0,"CpuRealtimePeriod":0,"CpuRealtimeRuntime":0,"CpusetCpus":"","CpusetMems":"","Devices":[],"DeviceCgroupRules":null,"DiskQuota":0,"KernelMemory":0,"MemoryReservation":0,"MemorySwap":0,"MemorySwappiness":-1,"OomKillDisable":false,"PidsLimit":0,"Ulimits":null,"CpuCount":0,"CpuPercent":0,"IOMaximumIOps":0,"IOMaximumBandwidth":0,"MaskedPaths":null,"ReadonlyPaths":null},"NetworkingConfig":{"EndpointsConfig":{}}}

INFO: 2018/10/16 18:03:15.382046 Creating container with WEAVE_CIDR "net:10.1.0.0/24"
DEBU: 2018/10/16 18:03:15.393442 <-requestBody: {"AttachStderr":false,"AttachStdin":false,"AttachStdout":false,"Cmd":["nginx","-g","daemon off;"],"Domainname":"","Entrypoint":["/w/w"],"Env":["WEAVE_CIDR=net:10.1.0.0/24"],"HostConfig":{"AutoRemove":false,"Binds":["/var/lib/docker/volumes/b4b8c62d481a78558cb938cbfe913c1fced0316a2d72862bdef39aa10600efc2/_data:/w:ro"],"BlkioDeviceReadBps":null,"BlkioDeviceReadIOps":null,"BlkioDeviceWriteBps":null,"BlkioDeviceWriteIOps":null,"BlkioWeight":0,"BlkioWeightDevice":[],"CapAdd":null,"CapDrop":null,"Cgroup":"","CgroupParent":"","ConsoleSize":[0,0],"ContainerIDFile":"","CpuCount":0,"CpuPercent":0,"CpuPeriod":0,"CpuQuota":0,"CpuRealtimePeriod":0,"CpuRealtimeRuntime":0,"CpuShares":0,"CpusetCpus":"","CpusetMems":"","DeviceCgroupRules":null,"Devices":[],"DiskQuota":0,"Dns":["172.17.0.1"],"DnsOptions":[],"DnsSearch":["node.intern."],"ExtraHosts":null,"GroupAdd":null,"IOMaximumBandwidth":0,"IOMaximumIOps":0,"IpcMode":"","Isolation":"","KernelMemory":0,"Links":null,"LogConfig":{"Config":{},"Type":""},"MaskedPaths":null,"Memory":0,"MemoryReservation":0,"MemorySwap":0,"MemorySwappiness":-1,"NanoCpus":0,"NetworkMode":"default","OomKillDisable":false,"OomScoreAdj":0,"PidMode":"","PidsLimit":0,"PortBindings":{},"Privileged":false,"PublishAllPorts":false,"ReadonlyPaths":null,"ReadonlyRootfs":false,"RestartPolicy":{"MaximumRetryCount":0,"Name":"no"},"SecurityOpt":null,"ShmSize":0,"UTSMode":"","Ulimits":null,"UsernsMode":"","VolumeDriver":"","VolumesFrom":null},"Hostname":"","Image":"nginx","Labels":{},"NetworkingConfig":{"EndpointsConfig":{}},"OnBuild":null,"OpenStdin":false,"StdinOnce":false,"Tty":false,"User":"","Volumes":{},"WorkingDir":""}
DEBU: 2018/10/16 18:03:15.435996 Response from target: 201 Created map[Content-Length:[90] Api-Version:[1.38] Content-Type:[application/json] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:03:15 GMT]]
INFO: 2018/10/16 18:03:15.437953 POST /v1.38/containers/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516/wait?condition=next-exit
DEBU: 2018/10/16 18:03:15.441400 Response from target: 200 OK map[Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:03:15 GMT] Api-Version:[1.38] Content-Type:[application/json] Docker-Experimental:[false] Ostype:[linux]]
INFO: 2018/10/16 18:03:15.442312 POST /v1.38/containers/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516/start
DEBU: 2018/10/16 18:03:15.884670 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:03:15.930080 Wait for start of container 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516
DEBU: 2018/10/16 18:03:15.937696 [net] ContainerStarted: 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516
DEBU: 2018/10/16 18:03:15.940932 [net] ContainerStarted: 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516
INFO: 2018/10/16 18:03:15.944721 Attaching container 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516 with WEAVE_CIDR "net:10.1.0.0/24" to weave network
DEBU: 2018/10/16 18:03:15.944771 weave POST to http://127.0.0.1:6784/ip/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516/10.1.0.0/24 with map[check-alive:[true]]
DEBU: 2018/10/16 18:03:15.945849 [http] POST /ip/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516/10.1.0.0/24
DEBU: 2018/10/16 18:03:15.952106 [allocator 00:00:00:00:00:01]: Allocated 10.1.0.4 for 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516 in 10.1.0.0/24
DEBU: 2018/10/16 18:03:15.956775 Running image "weaveworks/weaveexec:2.4.0"; entrypoint=["sh"]; cmd="[-c echo '# created by Weave - BEGIN\n# container hostname\n10.1.0.4        88]"; binds=["/var/lib/docker/containers/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516:/container"]
DEBU: 2018/10/16 18:03:15.992870 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:03:16.405025 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:03:16.475536 [net] ContainerStarted: eb6cf139436671a44d5b4e9dd2fac45663e4827de869699178785d6e1e2c0ba7
DEBU: 2018/10/16 18:03:16.478060 [net] ContainerStarted: eb6cf139436671a44d5b4e9dd2fac45663e4827de869699178785d6e1e2c0ba7
DEBU: 2018/10/16 18:03:16.650522 weave PUT to http://127.0.0.1:6784/name/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516/10.1.0.4 with map[fqdn:[885125c15ad2.]]
DEBU: 2018/10/16 18:03:16.650726 Discovered local MAC d6:ed:99:ef:1c:35
DEBU: 2018/10/16 18:03:16.651048 [http] PUT /name/885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516/10.1.0.4
INFO: 2018/10/16 18:03:16.651150 [nameserver 00:00:00:00:00:01] Ignoring registration 885125c15ad2. 10.1.0.4 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516 (not a subdomain of node.intern.)
DEBU: 2018/10/16 18:03:16.651314 Response from target: 204 No Content map[Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:03:15 GMT]]
DEBU: 2018/10/16 18:03:17.564136 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:03:17.637064 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:03:24.682414 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:03:25.334020 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:03:25.350041 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:03:25.885054 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:03:25.993320 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:03:27.564661 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:03:27.638030 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:03:33.767461 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:03:35.334919 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:03:35.351820 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:03:35.885985 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:03:35.994030 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:03:37.565604 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:03:37.638847 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:03:45.335864 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:03:45.353263 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:03:45.886880 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:03:45.995131 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:03:46.402284 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:03:47.566468 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:03:47.639272 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:03:54.684620 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:03:55.336755 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:03:55.352426 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:03:55.887303 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:03:55.995546 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:03:57.566935 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:03:57.640164 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:04:03.767303 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:04:05.337898 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:04:05.352717 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:04:05.888220 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:04:05.996485 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
INFO: 2018/10/16 18:04:07.412826 GET /_ping
DEBU: 2018/10/16 18:04:07.414978 Response from target: 200 OK map[Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:04:07 GMT] Content-Length:[2] Content-Type:[text/plain; charset=utf-8] Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux]]
INFO: 2018/10/16 18:04:07.421791 POST /v1.38/containers/885125/stop
INFO: 2018/10/16 18:04:07.431366 POST /v1.38/containers/735490/stop
INFO: 2018/10/16 18:04:07.431721 POST /v1.38/containers/005214/stop
INFO: 2018/10/16 18:04:07.431987 POST /v1.38/containers/eeb57f/stop
DEBU: 2018/10/16 18:04:07.569798 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:04:07.643507 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:04:08.078146 [allocator 00:00:00:00:00:01]: Container 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516 died; noting to remove later
DEBU: 2018/10/16 18:04:08.158936 [allocator 00:00:00:00:00:01]: Container 0052144510f6c01e1cff8661d881d24cedcc0f016153fc5a2d34f3f0ac92f4cb died; noting to remove later
DEBU: 2018/10/16 18:04:08.175838 [allocator 00:00:00:00:00:01]: Container 735490795cf2b54c077001ee14a1582a7b93feead908c76b79b1f0f575b1d7d2 died; noting to remove later
DEBU: 2018/10/16 18:04:08.205452 [allocator 00:00:00:00:00:01]: Container eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242 died; noting to remove later
DEBU: 2018/10/16 18:04:08.332276 Response from target: 204 No Content map[Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:04:08 GMT] Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux]]
DEBU: 2018/10/16 18:04:08.451849 Response from target: 204 No Content map[Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:04:08 GMT]]
DEBU: 2018/10/16 18:04:08.508355 Response from target: 204 No Content map[Ostype:[linux] Server:[Docker/18.06.0-ce (linux)] Date:[Tue, 16 Oct 2018 18:04:08 GMT] Api-Version:[1.38] Docker-Experimental:[false]]
DEBU: 2018/10/16 18:04:08.562276 Response from target: 204 No Content map[Date:[Tue, 16 Oct 2018 18:04:08 GMT] Api-Version:[1.38] Docker-Experimental:[false] Ostype:[linux] Server:[Docker/18.06.0-ce (linux)]]
DEBU: 2018/10/16 18:04:15.338557 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:04:15.353020 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:04:15.889096 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:04:15.999007 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:04:16.402088 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:04:17.568673 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:04:17.644612 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:04:25.339645 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:04:25.353585 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:04:25.889706 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:04:25.998806 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:04:27.569463 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:04:27.645335 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:04:33.768074 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:04:35.340311 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:04:35.354905 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:04:35.890912 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:04:35.999645 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:04:37.570049 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:04:37.645753 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:04:40.155952 [allocator 00:00:00:00:00:01]: Removed addresses for container eeb57f6f00e454a0b53f16f1d912e0e881afffb97a97af308368e3a0b0768242
DEBU: 2018/10/16 18:04:40.158638 [allocator 00:00:00:00:00:01]: Removed addresses for container 885125c15ad23d823021dbdea8b5aea3e89555debe16b19ed0865eeb625bd516
DEBU: 2018/10/16 18:04:40.161221 [allocator 00:00:00:00:00:01]: Removed addresses for container 0052144510f6c01e1cff8661d881d24cedcc0f016153fc5a2d34f3f0ac92f4cb
DEBU: 2018/10/16 18:04:40.164397 [allocator 00:00:00:00:00:01]: Removed addresses for container 735490795cf2b54c077001ee14a1582a7b93feead908c76b79b1f0f575b1d7d2
DEBU: 2018/10/16 18:04:45.341246 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:04:45.355245 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:04:45.891810 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:04:46.000541 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:04:46.402214 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:04:47.570382 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:04:47.646670 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:04:55.341687 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:04:55.354681 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:04:55.746949 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendFragTest
DEBU: 2018/10/16 18:04:55.753904 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleFragTestAck
DEBU: 2018/10/16 18:04:55.892199 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:04:56.000948 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:04:57.571369 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:04:57.647087 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:05:03.768010 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:05:05.342563 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:05:05.355091 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:05:05.893099 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:05:06.001347 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:05:07.571170 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:05:07.647438 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:05:15.343432 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:05:15.354998 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:05:15.894006 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:05:16.001813 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:05:16.401440 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:05:17.571611 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:05:17.648408 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:05:24.683982 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:05:25.344338 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:05:25.355429 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:05:25.894931 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:05:26.002652 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:05:27.572521 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:05:27.649273 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:05:33.767265 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:05:35.345240 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:05:35.355779 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:05:35.895791 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:05:36.002874 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:05:37.573465 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:05:37.649658 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:05:45.345834 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:05:45.356674 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:05:45.896202 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:05:46.003950 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:05:46.400918 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:05:47.573843 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:05:47.651063 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:05:54.683786 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:05:55.345999 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:05:55.356630 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:05:55.896598 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:05:56.004367 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:05:57.574720 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:05:57.651675 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:06:03.766873 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:06:05.346581 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:06:05.359425 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:06:05.897041 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:06:06.005270 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:06:07.575139 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:06:07.652874 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:06:15.347364 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:06:15.357477 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:06:15.897937 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:06:16.005998 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:06:16.400981 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:06:17.575694 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:06:17.653742 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:06:19.786601 Expired MAC b2:2c:29:81:5b:14 at 00:00:00:00:00:01(node1)
DEBU: 2018/10/16 18:06:19.786641 Expired MAC 3a:c3:d3:a8:e9:ed at 00:00:00:00:00:01(node1)
DEBU: 2018/10/16 18:06:19.786658 Expired MAC a6:e4:af:50:9f:9a at 00:00:00:00:00:01(node1)
DEBU: 2018/10/16 18:06:19.786674 Expired MAC ea:be:51:49:f5:88 at 00:00:00:00:00:01(node1)
DEBU: 2018/10/16 18:06:24.683671 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:06:25.347754 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:06:25.359188 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:06:25.898803 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:06:26.007196 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:06:27.575796 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:06:27.655421 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:06:33.770073 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:06:35.348675 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:06:35.359782 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:06:35.899740 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:06:36.007997 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:06:37.576315 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:06:37.656561 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:06:45.349543 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:06:45.359141 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:06:45.900105 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:06:46.008854 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:06:47.576701 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:06:47.657966 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:06:54.683507 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:06:55.350461 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:06:55.358914 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:06:55.901018 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:06:56.009644 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:06:57.577528 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:06:57.658856 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:07:03.766281 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:07:05.350856 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:07:05.359263 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:07:05.901455 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:07:06.010657 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:07:07.577523 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:07:07.659281 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:07:15.351765 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:07:15.359948 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:07:15.901814 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:07:16.011563 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:07:16.401764 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:07:17.471847 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendFragTest
DEBU: 2018/10/16 18:07:17.476311 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleFragTestAck
DEBU: 2018/10/16 18:07:17.578309 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:07:17.660652 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:07:24.683629 [allocator 00:00:00:00:00:01]: Allocator.OnGossip: 631 bytes
DEBU: 2018/10/16 18:07:25.352728 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:07:25.359557 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:07:25.902713 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:07:26.011962 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:07:27.578890 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:07:27.661071 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:07:35.361186 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:07:35.361484 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
DEBU: 2018/10/16 18:07:35.903133 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: sendHeartbeat
DEBU: 2018/10/16 18:07:36.012384 sleeve ->[20.20.20.22:6783|00:00:00:00:00:02(node2)]: handleHeartbeat
DEBU: 2018/10/16 18:07:37.579735 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: handleHeartbeat
DEBU: 2018/10/16 18:07:37.662442 sleeve ->[20.20.20.23:6783|00:00:00:00:00:03(node3)]: sendHeartbeat
DEBU: 2018/10/16 18:07:45.363478 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: sendHeartbeat
DEBU: 2018/10/16 18:07:45.363636 sleeve ->[20.20.20.24:6783|00:00:00:00:00:04(node4)]: handleHeartbeat
MikeMichel commented 5 years ago

@brb this should be enough info to remove the label, right?

predakanga commented 5 years ago

I'm also experiencing this issue. Additionally, when the system is in this state routing to weave addresses fails with "No route to host".

Weave version: 2.4.1 Docker version: 18.06.1-ce Linux version: 4.4.0-134-generic (Ubuntu 16.04.5)

Logs: weave.log kern.log docker.log

Potentially interesting factors: Weave is used as API proxy Weave is using encryption Weave is connecting to one peer over a trusted subnet w/ fastdp, all others with encrypted sleeve System is running prometheus-node-exporter (puts quite a lot of stress on Docker)

Also knocked up a quick script to delete the dangling links (requires pyroute2 and recent util-linux for lsns):

#!/usr/bin/env python

from __future__ import print_function

import subprocess
from pyroute2 import IPRoute

THRESHOLD = 100

if __name__ == "__main__":
        ipr = IPRoute()
        # Enumerate the links, create an ifname lookup table
        links = {x['index']: dict(x['attrs']) for x in ipr.get_links('all')}
        ifs = {v['IFLA_IFNAME']: k for k, v in links.iteritems()}
        # Fetch the index of the 'weave' bridge interface and enumerate it's children
        bridge = ifs['weave']
        veths = [k for k, v in links.iteritems() if v['IFLA_IFNAME'].startswith('vethwepl') and 'IFLA_MASTER' in v and v['IFLA_MASTER'] == bridge]
        # Look up valid netnsids - should find a native way to do this
        output = subprocess.check_output(['lsns', '-t', 'net'])
        lines = output.split("\n")
        valid_netnsids = set(x.split()[5] for x in lines[1:-1])
        int_netnsids = set(int(x) for x in valid_netnsids if x != 'unassigned')
        # Check whether the netnsid on each veth is valid
        valid_veths = set()
        invalid_veths = set()
        valid = invalid = 0
        for idx in veths:
                if 'IFLA_LINK_NETNSID' not in links[idx]:
                        continue
                if links[idx]['IFLA_LINK_NETNSID'] in int_netnsids:
                        valid_veths.add(idx)
                else:
                        invalid_veths.add(idx)
        print("Found {} valid, {} invalid veth pairs".format(len(valid_veths), len(invalid_veths)))
        # Only act if we're above a threshold, to make reproducing easier
        if len(invalid_veths) > THRESHOLD:
                print("More than {} invalid veths; culling them".format(THRESHOLD))
                for idx in invalid_veths:
                        ipr.link('del', index=idx)
jzaefferer commented 5 years ago

Also knocked up a quick script to delete the dangling links (requires pyroute2 and recent util-linux for lsns):

We're using a bash script, with ip a and ip link delete, to (probably) to the same thing:

#!/bin/bash

ip a | grep 'vethwepl.*\@' -oP | while read -r line ; do
    veth=${line::-1}
    if [[ $veth =~ [0-9] ]]; then
      echo check $veth
      pid=$(echo $veth | tr -dc '0-9')
      if ! ps -p $pid > /dev/null; then
        echo deleting $veth
        ip link delete $veth >&2
      else
        echo $veth still running
      fi
    else
      echo $veth veth has no number in it and will not be deleted
    fi
done
thetooth commented 5 years ago

Also having this issue, we run weave with nomad in a 3 node cluster and various satellite applications connecting in over weave. But this was caused by setting up a periodic job that ran every minute, so it eventually stopped running, only after taking out the entire cluster :100:

Pretty much identical configuration and logs to @predakanga. The containers are being removed, there is no DNS entries left behind and weave status ipam shows 130 active which matches the number of containers running.

Kinda ironic running the script above using periodic to work around periodic jobs not working lol

murali-reddy commented 5 years ago

@MikeMichel @predakanga @thetooth thanks for providing the logs. I will try to reproduce and do root cause analysis.

murali-reddy commented 5 years ago

Just followed the steps I am able to reproduce the issue. Will try to idetify the cause.

predakanga commented 5 years ago

Possibly related, I just SSHed in to find that several (about 10) of our task containers had hung during their launch, over a period of 4 days.

Each hung container looks the same, so I picked a random one to gather information:

Docker lists the container as "running" The only process running in the container is the weave "/w/w" entrypoint The stacktrace of the process is attached here: entrypoint stack.txt The vethwe interface does not exist inside the container (confirmed using docker exec), the standard eth0 veth does exist. The relevant section of the Weave logs is attached here: entrypoint weave.txt - note that the hung container is ID fd54060031b0, no 'Attaching container' message is ever printed for it

Vinutha-Garimella commented 5 years ago

Also knocked up a quick script to delete the dangling links (requires pyroute2 and recent util-linux for lsns):

We're using a bash script, with ip a and ip link delete, to (probably) to the same thing:

#!/bin/bash

ip a | grep 'vethwepl.*\@' -oP | while read -r line ; do
    veth=${line::-1}
    if [[ $veth =~ [0-9] ]]; then
      echo check $veth
      pid=$(echo $veth | tr -dc '0-9')
      if ! ps -p $pid > /dev/null; then
        echo deleting $veth
        ip link delete $veth >&2
      else
        echo $veth still running
      fi
    else
      echo $veth veth has no number in it and will not be deleted
    fi
done

@jzaefferer Thanks this script worked and removed all the dangling links stored in weave

rorysavage77 commented 5 years ago

Also knocked up a quick script to delete the dangling links (requires pyroute2 and recent util-linux for lsns):

Must have been a good looking script ;)

avkonst commented 4 years ago

I have found the cause of this problem in the overnode script. The leaked IP interfaces are left when a container is created via weave docker proxy, but killed and removed via a docker directly. Once I moved the kill and rm to the weave proxy too, I have not seen this problem anymore.