Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Overlay mac cleanup issue on IP reuse #1934

Closed
fcrisciani opened this issue Sep 5, 2017 · 2 comments
Closed

Overlay mac cleanup issue on IP reuse #1934

fcrisciani opened this issue Sep 5, 2017 · 2 comments
Assignees
@fcrisciani

Comments

@fcrisciani
Copy link

There seem to be a race condition where the IP reuse brings the overlay namespace with wrong configuration.

The following log shows the issue:

Sep 01 11:19:34 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:34.691632056-07:00" level=error msg="PeerDbAdd Key:10.255.0.6 02:42:0a:ff:00:06 Value:{eid:c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea vtep:[0 0 0 0 0 0 0 0 0 0 255 255 172 31 13 174] peerIPMask:[255 255 0 0] inSandbox:false isLocal:false}"
Sep 01 11:19:34 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:34.692078224-07:00" level=error msg="peerAddOp nid:y1j0b7yextgpf235djzark5k4 eid:c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea peerIP:10.255.0.6 peerMask:ffff0000 peerMac:02:42:0a:ff:00:06 vtep:172.31.13.174 l2Miss:false l3Miss:false"
Sep 01 11:19:36 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:36.955102682-07:00" level=debug msg="handleEpTableEvent ADD c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea R:{TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5.1.3bqyh9q5sqrx9l09de00k2e9b TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 fc2bfgdih5oldzl7wsvpcbps3 10.255.0.5 10.255.0.6 [&PortConfig{Name:,Protocol:TCP,TargetPort:80,PublishedPort:30025,}] [] [ded5b19256e9]}"
Sep 01 11:19:36 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:36.955324826-07:00" level=debug msg="addServiceBinding from handleEpTableEvent START for TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea p:0xc4229d7180 nid:y1j0b7yextgpf235djzark5k4 skey:{fc2bfgdih5oldzl7wsvpcbps3 30025:80/TCP}"
Sep 01 11:19:37 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:37.101710164-07:00" level=debug msg="addEndpointNameResolution c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 add_service:true sAliases:[] tAliases:[ded5b19256e9]"
Sep 01 11:19:37 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:37.102074320-07:00" level=debug msg="addContainerNameResolution c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5.1.3bqyh9q5sqrx9l09de00k2e9b"
Sep 01 11:19:37 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:37.110435532-07:00" level=debug msg="addServiceBinding from handleEpTableEvent END for TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea"
Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.748882483-07:00" level=debug msg="handleEpTableEvent DEL c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea R:{TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5.1.3bqyh9q5sqrx9l09de00k2e9b TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 fc2bfgdih5oldzl7wsvpcbps3 10.255.0.5 10.255.0.6 [&PortConfig{Name:,Protocol:TCP,TargetPort:80,PublishedPort:30025,}] [] [ded5b19256e9]}"
Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.749209708-07:00" level=debug msg="rmServiceBinding from handleEpTableEvent START for TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea p:0xc4229d7180 nid:y1j0b7yextgpf235djzark5k4 sKey:{fc2bfgdih5oldzl7wsvpcbps3 30025:80/TCP} deleteSvc:true"
Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.749414019-07:00" level=debug msg="rmServiceBinding c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea delete y1j0b7yextgpf235djzark5k4, p:0xc420a12a20 in loadbalancers len:0"
Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.832773581-07:00" level=error msg="PeerDbAdd Key:10.255.0.6 02:42:0a:ff:00:06 Value:{eid:f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb vtep:[0 0 0 0 0 0 0 0 0 0 255 255 172 31 13 68] peerIPMask:[255 255 0 0] inSandbox:false isLocal:false}"
Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.833233804-07:00" level=error msg="peerDeleteOp        pEntry:{eid:f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb vtep:[0 0 0 0 0 0 0 0 0 0 255 255 172 31 13 68] peerIPMask:[255 255 0 0] inSandbox:false isLocal:false}"
Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.833253781-07:00" level=error msg="peerDeleteOp nid:y1j0b7yextgpf235djzark5k4 eid:c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea peerIP:10.255.0.6 peerMask:ffff0000 peerMac:02:42:0a:ff:00:06 vtep:172.31.13.174"
Sep 01 11:19:40 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:40.226175623-07:00" level=debug msg="deleteEndpointNameResolution c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 rm_service:true suppress:false sAliases:[] tAliases:[ded5b19256e9]"
Sep 01 11:19:40 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:40.226573255-07:00" level=debug msg="delContainerNameResolution c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5.1.3bqyh9q5sqrx9l09de00k2e9b"
Sep 01 11:19:40 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:40.226593064-07:00" level=debug msg="rmServiceBinding from handleEpTableEvent END for TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea"
Sep 01 11:19:42 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:42.265987122-07:00" level=debug msg="addServiceInfoToCluster START for TestServiceDNSRRClientc9b055e0-1094-4f52-931d-87ae717f7440 f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb"
Sep 01 11:19:42 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:42.266202534-07:00" level=debug msg="addServiceBinding from addServiceInfoToCluster START for TestServiceDNSRRClientc9b055e0-1094-4f52-931d-87ae717f7440 f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb p:0xc423144d80 nid:y1j0b7yextgpf235djzark5k4 skey:{mbwa7d5enbor1tez3c0c28w3o 30026:80/TCP}"
Sep 01 11:19:42 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:42.412264976-07:00" level=debug msg="addEndpointNameResolution f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb TestServiceDNSRRClientc9b055e0-1094-4f52-931d-87ae717f7440 add_service:true sAliases:[] tAliases:[5bdbdf36a068]"
Sep 01 11:19:42 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:42.412683010-07:00" level=debug msg="addContainerNameResolution f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb TestServiceDNSRRClientc9b055e0-1094-4f52-931d-87ae717f7440.1.k2yiwldpltl1rexhshm6xw109"
Sep 01 11:19:42 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:42.412891701-07:00" level=debug msg="addServiceBinding from addServiceInfoToCluster END for TestServiceDNSRRClientc9b055e0-1094-4f52-931d-87ae717f7440 f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb"
Sep 01 11:19:42 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:42.413161694-07:00" level=debug msg="addServiceInfoToCluster END for TestServiceDNSRRClientc9b055e0-1094-4f52-931d-87ae717f7440 f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb"

The first container (leaving on a remote node) is c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea that gets created and added to the peerDB:

Sep 01 11:19:34 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:34.691632056-07:00" level=error msg="PeerDbAdd Key:10.255.0.6 02:42:0a:ff:00:06 Value:{eid:c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea vtep:[0 0 0 0 0 0 0 0 0 0 255 255 172 31 13 174] peerIPMask:[255 255 0 0] inSandbox:false isLocal:false}"
[...]
Sep 01 11:19:37 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:37.110435532-07:00" level=debug msg="addServiceBinding from handleEpTableEvent END for TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea"

After some time it goes down

Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.748882483-07:00" level=debug msg="handleEpTableEvent DEL c987bed674d82784df8000eed19f7890a633dede5461fac4595c4cf0e250d2ea R:{TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5.1.3bqyh9q5sqrx9l09de00k2e9b TestServiceConnectivitySimpleServiceICMPTesterc9b055e0-1094-4f5 fc2bfgdih5oldzl7wsvpcbps3 10.255.0.5 10.255.0.6 [&PortConfig{Name:,Protocol:TCP,TargetPort:80,PublishedPort:30025,}] [] [ded5b19256e9]}"

Locally while the deletion is happening another container is spawned and reuses the IP because now is free

Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.832773581-07:00" level=error msg="PeerDbAdd Key:10.255.0.6 02:42:0a:ff:00:06 Value:{eid:f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb vtep:[0 0 0 0 0 0 0 0 0 0 255 255 172 31 13 68] peerIPMask:[255 255 0 0] inSandbox:false isLocal:false}"

At this point when the peerDelete fetches the entry in the DB this one changed:

Sep 01 11:19:39 E2E-DEV-flaviocrisciani-117ECD2A-linux-1 dockerd[13802]: time="2017-09-01T11:19:39.833233804-07:00" level=error msg="peerDeleteOp        pEntry:{eid:f7abd893cc943ce7fa205bf4d1392b7d6f941ba3fedc6edc5726c7ff0d2a13bb vtep:[0 0 0 0 0 0 0 0 0 0 255 255 172 31 13 68] peerIPMask:[255 255 0 0] inSandbox:false isLocal:false}"

For this reason there would not be any namespace configuration change or deletion: https://github.com/docker/libnetwork/blob/master/drivers/overlay/peerdb.go#L407

So the internal namespace is still holding the wrong config:

root@E2E-DEV-flaviocrisciani-117ECD2A-linux-1:/home/docker# bridge fdb show | grep 02:42:0a:ff:00:06                                                                                                                                                                            
02:42:0a:ff:00:06 dev vxlan0 master br0                                                                                                                                                                                                                                         
02:42:0a:ff:00:06 dev vxlan0 dst 172.31.13.174 link-netnsid 0 self permanent

After that the entry is garbage collected the proper config has to be:

02:42:0a:ff:00:06 dev veth68 master br0
@fcrisciani fcrisciani self-assigned this Sep 5, 2017
This was referenced Sep 5, 2017
Closed
Merged
@m4r10k
Copy link

m4r10k commented Sep 20, 2017 •
edited
Loading

I guess we are facing the same problem on one of our Docker hosts. Is there a possible (manual) workaround?

Log output

There are thousands of these messages.

Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247753229+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff5c9c9e489cddb048fa047687bf6f1cbc87273787f1f982bad7c1c651f30599 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247774266+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff6755701ed48531a6e44c2f656157bdef7b976c22e64041454d91f9e9217ece aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247796390+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff727cb6531f58a467e1ccf087415dd3e8507e999eb112999d56cecb2c105855 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247817418+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff72f127327fde39df533708580cd809eb3e86c6545a45f32d8cd5a965920f9f aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247843348+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff75b0d82975ac8836cd116de2c6821f9dfb89a1f0dbc5b2a0365cb708a2fad8 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247866074+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff8d17cbf68301a34e2d5cbf95c9b65c541a31d2eb6eb38ea1f4d7aa2b49cfb1 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247888591+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff8de8a098b80fa2621bd85ad0806c9186e0dd792c2c83295cfed516b0026878 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247913992+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff9164ea327490e95993f20383df509097f00d02fa8318963fa0f898a02a55a2 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247939435+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff9620d262ae3b55eccaea6a998485cfb0c8c698a776b26ef6602780d764b31d aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247960312+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff9850e0c07d123fc9265bf18bc09f2aab10a92bd0d73bed4b95922694af97dc aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.247984184+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ff9d5c20cb1fa518aa836af23786dc46235259186e0878a4c5c2f01631602afd aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248008815+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ffc9f6169ea2dc717bf483d69924bf50e6fc822959d852757c75e8f810829e03 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248032443+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ffcbf5e02f473b9e92e1e7148043808630bb24e7673eca6353186c44a9b36069 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248052698+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ffd053f9a880e6a5ce8aa0cc7fd7d3778bd8298e76eefa23c96f5e90c5762c64 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248083485+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ffdad4c3bb1bcf0658d989a976ea649909a34f1885ea51d52ed584dc7a756cf1 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248109897+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ffea692f35ff70409a742a53b928cccd3545cb1841a2fb31c0856e7fde61efaa aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248132964+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app ffeb43e46c737a7b1675490ad8160688c17fa12f740b5c04b891749e37ab8ff1 aborted c.serviceBindings[skey] !ok"
Sep 20 07:49:46 xyz2612 dockerd[2811]: time="2017-09-20T07:49:46.248153908+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app fff2451389eaeb49d86456e2f977fbb934c0ab077122e58e4941ffdf120a8a2d aborted c.serviceBindings[skey] !ok"

And there are these messages in between:

Sep 20 07:49:36 lalelu kernel: [454679.559067] IPVS: __ip_vs_del_service: enter
Sep 20 07:49:36 lalelu dockerd[2811]: time="2017-09-20T07:49:36.431306075+02:00" level=warning msg="Deleting bridge mac mac 02:42:0a:00:0f:02 failed, no such file or directory"
Sep 20 07:49:39 lalelu kernel: [454682.398939] IPVS: __ip_vs_del_service: enter
Sep 20 07:49:39 lalelu dockerd[2811]: time="2017-09-20T07:49:39.267408425+02:00" level=warning msg="Deleting bridge mac mac 02:42:0a:00:0f:05 failed, no such file or directory"

Docker version

Client:
Version: 17.06.0-ce
API version: 1.30
Go version: go1.8.3
Git commit: 02c1d87
Built: Fri Jun 23 21:23:31 2017
OS/Arch: linux/amd64

Server:
Version: 17.06.0-ce
API version: 1.30 (minimum version 1.12)
Go version: go1.8.3
Git commit: 02c1d87
Built: Fri Jun 23 21:19:04 2017
OS/Arch: linux/amd64
Experimental: false

@m4r10k
Copy link

m4r10k commented Sep 20, 2017

After a restart of the container which is connected to the network ips-tst_app the following messages are appearing, and afterwards, it seems that the host is OK.

Sep 20 07:57:33 xyz612 dockerd[2811]: time="2017-09-20T07:57:33.836210062+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app fffc581ee7d0c4e97da1efbd02fbe2f009e7902fd877b1bc6b01308acebf7cd6 aborted c.serviceBindings[skey] !ok"
Sep 20 07:57:36 xyz612 kernel: [455159.281640] br0: port 2(veth0) entered disabled state
Sep 20 07:57:36 xyz612 kernel: [455159.281674] br0: port 1(vxlan0) entered disabled state
Sep 20 07:57:36 xyz612 kernel: [455159.283548] ov-001010-hb0rf: renamed from br0
Sep 20 07:57:36 xyz612 kernel: [455159.307604] device veth0 left promiscuous mode
Sep 20 07:57:36 xyz612 kernel: [455159.307648] ov-001010-hb0rf: port 2(veth0) entered disabled state
Sep 20 07:57:36 xyz612 kernel: [455159.331452] device vxlan0 left promiscuous mode
Sep 20 07:57:36 xyz612 kernel: [455159.331490] ov-001010-hb0rf: port 1(vxlan0) entered disabled state
Sep 20 07:57:36 xyz612 kernel: [455159.348449] IPVS: __ip_vs_del_service: enter
Sep 20 07:57:36 xyz612 kernel: [455159.397064] vx-001010-hb0rf: renamed from vxlan0
Sep 20 07:57:36 xyz612 kernel: [455159.451042] veth79d2918: renamed from veth0
Sep 20 07:57:36 xyz612 systemd-udevd[53214]: Could not generate persistent MAC address for vx-001010-hb0rf: No such file or directory
Sep 20 07:57:36 xyz612 systemd-udevd[53286]: Could not generate persistent MAC address for veth79d2918: No such file or directory
Sep 20 07:57:36 xyz612 kernel: [455159.541159] veth42c5948: renamed from eth0
Sep 20 07:57:36 xyz612 kernel: [455159.665993] docker_gwbridge: port 3(veth2ddab6e) entered disabled state
Sep 20 07:57:36 xyz612 kernel: [455159.666112] veth981d581: renamed from eth1
Sep 20 07:57:36 xyz612 kernel: [455159.701562] docker_gwbridge: port 3(veth2ddab6e) entered disabled state
Sep 20 07:57:36 xyz612 kernel: [455159.703858] device veth2ddab6e left promiscuous mode
Sep 20 07:57:36 xyz612 kernel: [455159.703860] docker_gwbridge: port 3(veth2ddab6e) entered disabled state
Sep 20 07:57:37 xyz612 kernel: [455160.283546] IPVS: Creating netns size=2192 id=7600
Sep 20 07:57:37 xyz612 kernel: [455160.343716] br0: renamed from ov-001010-hb0rf
Sep 20 07:57:37 xyz612 systemd-udevd[53836]: Could not generate persistent MAC address for vx-001010-hb0rf: No such file or directory
Sep 20 07:57:37 xyz612 kernel: [455160.375925] vxlan0: renamed from vx-001010-hb0rf
Sep 20 07:57:37 xyz612 kernel: [455160.391593] device vxlan0 entered promiscuous mode
Sep 20 07:57:37 xyz612 kernel: [455160.391882] br0: port 1(vxlan0) entered forwarding state
Sep 20 07:57:37 xyz612 kernel: [455160.391888] br0: port 1(vxlan0) entered forwarding state
Sep 20 07:57:37 xyz612 systemd-udevd[53960]: Could not generate persistent MAC address for vethe259ec6: No such file or directory
Sep 20 07:57:37 xyz612 systemd-udevd[53961]: Could not generate persistent MAC address for veth016c2a0: No such file or directory
Sep 20 07:57:37 xyz612 kernel: [455160.459889] veth0: renamed from veth016c2a0
Sep 20 07:57:37 xyz612 kernel: [455160.479689] device veth0 entered promiscuous mode
Sep 20 07:57:37 xyz612 kernel: [455160.479885] br0: port 2(veth0) entered forwarding state
Sep 20 07:57:37 xyz612 kernel: [455160.479890] br0: port 2(veth0) entered forwarding state
Sep 20 07:57:37 xyz612 systemd-udevd[54061]: Could not generate persistent MAC address for veth4c14630: No such file or directory
Sep 20 07:57:37 xyz612 kernel: [455160.482414] device vethd2389c6 entered promiscuous mode
Sep 20 07:57:37 xyz612 kernel: [455160.482521] IPv6: ADDRCONF(NETDEV_UP): vethd2389c6: link is not ready
Sep 20 07:57:37 xyz612 kernel: [455160.482526] docker_gwbridge: port 3(vethd2389c6) entered forwarding state
Sep 20 07:57:37 xyz612 kernel: [455160.482541] docker_gwbridge: port 3(vethd2389c6) entered forwarding state
Sep 20 07:57:37 xyz612 systemd-udevd[53836]: Could not generate persistent MAC address for vethd2389c6: No such file or directory
Sep 20 07:57:37 xyz612 kernel: [455160.630987] IPVS: Creating netns size=2192 id=7601
Sep 20 07:57:37 xyz612 kernel: [455160.796281] eth0: renamed from vethe259ec6
Sep 20 07:57:37 xyz612 kernel: [455160.823932] docker_gwbridge: port 3(vethd2389c6) entered disabled state
Sep 20 07:57:37 xyz612 kernel: [455160.839883] eth1: renamed from veth4c14630
Sep 20 07:57:37 xyz612 kernel: [455160.856277] IPv6: ADDRCONF(NETDEV_CHANGE): vethd2389c6: link becomes ready
Sep 20 07:57:37 xyz612 kernel: [455160.856383] docker_gwbridge: port 3(vethd2389c6) entered forwarding state
Sep 20 07:57:37 xyz612 kernel: [455160.856406] docker_gwbridge: port 3(vethd2389c6) entered forwarding state
Sep 20 07:57:38 xyz612 ntpd[2934]: bind(75) AF_INET6 fe80::4802:e5ff:feed:afcf%15256#123 flags 0x11 failed: Cannot assign requested address
Sep 20 07:57:38 xyz612 ntpd[2934]: unable to create socket on vethd2389c6 (86) for fe80::4802:e5ff:feed:afcf%15256#123
Sep 20 07:57:38 xyz612 ntpd[2934]: failed to init interface for address fe80::4802:e5ff:feed:afcf%15256
Sep 20 07:57:38 xyz612 ntpd[2934]: Deleting interface #39 veth2ddab6e, fe80::e076:fff:feb5:460a%55#123, interface stats: received=0, sent=0, dropped=0, active_time=455152 secs
Sep 20 07:57:40 xyz612 kernel: [455163.388843] IPVS: __ip_vs_del_service: enter
Sep 20 07:57:40 xyz612 dockerd[2811]: time="2017-09-20T07:57:40.268036339+02:00" level=warning msg="Deleting bridge mac mac 02:42:0a:00:0f:05 failed, no such file or directory"
Sep 20 07:57:40 xyz612 ntpd[2934]: Listen normally on 87 vethd2389c6 [fe80::4802:e5ff:feed:afcf%15256]:123
Sep 20 07:57:40 xyz612 ntpd[2934]: new interface(s) found: waking up resolver
Sep 20 07:57:43 xyz612 dockerd[2811]: time="2017-09-20T07:57:43.666238822+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app e16fa7dcc3b8ab0fc730c0cb548df695efdb87550afc98ed397a4381fe840032 aborted c.serviceBindings[skey] !ok"
Sep 20 07:57:44 xyz612 dockerd[2811]: time="2017-09-20T07:57:44.584667311+02:00" level=info msg="Node join event for xyz9208-b012f944c540/x.y.z.208"
Sep 20 07:57:45 xyz612 dockerd[2811]: time="2017-09-20T07:57:45.423050635+02:00" level=warning msg="Deleting bridge mac mac 02:42:0a:00:0f:02 failed, no such file or directory"
Sep 20 07:57:45 xyz612 kernel: [455168.548329] IPVS: __ip_vs_del_service: enter
Sep 20 07:57:48 xyz612 dockerd[2811]: time="2017-09-20T07:57:48.664301647+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app a6fda96dd23892cbc9f8fa319480aab55171c68f459a3275f0b32d139cfeab08 aborted c.serviceBindings[skey] !ok"
Sep 20 07:57:50 xyz612 dockerd[2811]: time="2017-09-20T07:57:50.038601678+02:00" level=info msg="Node join event for xyz9206-2d02007f11a5/x.y.z.206"
Sep 20 07:57:50 xyz612 dockerd[2811]: time="2017-09-20T07:57:50.263754403+02:00" level=warning msg="Deleting bridge mac mac 02:42:0a:00:0f:05 failed, no such file or directory"
Sep 20 07:57:50 xyz612 kernel: [455173.388952] IPVS: __ip_vs_del_service: enter
Sep 20 07:57:50 xyz612 dockerd[2811]: time="2017-09-20T07:57:50.464410185+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app 92d445efc6a00984f615014eddf0106e1105cec6a4cc9203867f5c5af9848d45 aborted c.serviceBindings[skey] !ok"
Sep 20 07:57:50 xyz612 dockerd[2811]: time="2017-09-20T07:57:50.464818109+02:00" level=warning msg="rmServiceBinding handleEpTableEvent ips-tst_app e16fa7dcc3b8ab0fc730c0cb548df695efdb87550afc98ed397a4381fe840032 aborted c.serviceBindings[skey] !ok"
Sep 20 07:57:52 xyz612 kernel: [455175.446906] br0: port 1(vxlan0) entered forwarding state
Sep 20 07:57:52 xyz612 kernel: [455175.510911] br0: port 2(veth0) entered forwarding state
Sep 20 07:57:52 xyz612 kernel: [455175.894923] docker_gwbridge: port 3(vethd2389c6) entered forwarding state
Sep 20 07:58:06 xyz612 postfix/smtpd[54778]: connect from localhost[127.0.0.1]
Sep 20 07:58:06 xyz612 postfix/smtpd[54778]: disconnect from localhost[127.0.0.1] quit=1 commands=1
Sep 20 07:58:06 xyz612 dockerd[2811]: time="2017-09-20T07:58:06.913232001+02:00" level=error msg="Bulk sync to node xyz9205-eb6cfeebf66f timed out"
Sep 20 07:58:14 xyz612 dockerd[2811]: time="2017-09-20T07:58:14.587368924+02:00" level=info msg="Node join event for xyz9205-eb6cfeebf66f/x.y.z.205"
Sep 20 07:58:20 xyz612 dockerd[2811]: time="2017-09-20T07:58:20.041266775+02:00" level=info msg="Node join event for xyz9206-2d02007f11a5/x.y.z.206"
Sep 20 07:58:44 xyz612 dockerd[2811]: time="2017-09-20T07:58:44.588864802+02:00" level=info msg="Node join event for xyz133-c708b900fbf3/a.y.z133"
Sep 20 07:58:44 xyz612 dockerd[2811]: time="2017-09-20T07:58:44.591482686+02:00" level=info msg="Node join event for xyz9206-2d02007f11a5/x.y.z.206"
Sep 20 07:58:56 xyz612 dockerd[2811]: time="2017-09-20T07:58:56.305058798+02:00" level=info msg="Node join event for xyz130-841c05c6f4df/a.y.z130"
Sep 20 07:59:14 xyz612 dockerd[2811]: time="2017-09-20T07:59:14.593619979+02:00" level=info msg="Node join event for xyz9204-5909a0dfa8f3/x.y.z.204"
Sep 20 07:59:14 xyz612 dockerd[2811]: time="2017-09-20T07:59:14.774074278+02:00" level=info msg="Node join event for xyz9207-213c0c051484/x.y.z.207"
Sep 20 07:59:20 xyz612 dockerd[2811]: time="2017-09-20T07:59:20.630070772+02:00" level=info msg="Node join event for xyz9205-eb6cfeebf66f/x.y.z.205"
Sep 20 07:59:26 xyz612 dockerd[2811]: time="2017-09-20T07:59:26.355214480+02:00" level=info msg="Node join event for xyz130-841c05c6f4df/a.y.z130"

Oh just to mention: we are using a lot of virtual ip addresses on this host because on this host we are running our border controller which routes the traffic from the outside LAN/WAN to the overlay services.

@sbrattla sbrattla mentioned this issue Sep 20, 2017
Closed
@Nossnevs Nossnevs mentioned this issue Sep 29, 2017
Closed
@fcrisciani fcrisciani mentioned this issue Oct 10, 2017
Closed
@schmunk42 schmunk42 mentioned this issue Oct 18, 2017
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@fcrisciani fcrisciani

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@fcrisciani @m4r10k