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.

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

Multi-Manager Docker Swarm goes out of sync Docker 1.12.3 #1771

Closed
Bartman250 opened this issue Nov 25, 2016 · 4 comments
Closed

Multi-Manager Docker Swarm goes out of sync Docker 1.12.3 #1771

Bartman250 opened this issue Nov 25, 2016 · 4 comments

Comments

@Bartman250
Copy link

Bartman250 commented Nov 25, 2016

Hello,

I have seen a couple of similar issues to this, but not for 1.12.3 and not for mulit-manager swarms.
I'm happy to merge with another if this is similar.

Summary:

After setting up a two node manager only swarm, the second node responds badly to docker network/docker service/docker node commands, either pausing for a long time or getting the error:

Error response from daemon: rpc error: code = 4 desc = context deadline exceeded

This also means that you can't kick off services from the second node.

What I’m trying to do:

I want to set up a multi manager swarm so that I can run a swarm between several servers (potential managed by different organisations) using external ports (i.e. servers not on the same vlan/subnet).

My test example for two servers on separate vlans within microsoft azure.

Here are the versions and info

(note: ip addresses/tokens have been obfuscated to protect the innocent).

Both servers are azure DS3 config - 4 cores, 14GB of ram

Ubuntu version is :

Distributor ID: Ubuntu
Description: Ubuntu 16.04.1 LTS
Release: 16.04
Codename: xenial

Docker version is:

Docker version 1.12.3, build 6b644ec

Docker info server 1

docker info
Containers: 6
Running: 0
Paused: 0
Stopped: 6
Images: 77
Server Version: 1.12.3
Storage Driver: aufs
Root Dir: /var/lib/docker/aufs
Backing Filesystem: extfs
Dirs: 69
Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: overlay bridge null host
Swarm: active
NodeID: clcle3y7pisfitqz9ni5dp6fj
Is Manager: true
ClusterID: 5qvbbpps63z4i2i0w7cpnlj1u
Managers: 2
Nodes: 2
Orchestration:
Task History Retention Limit: 5
Raft:
Snapshot Interval: 10000
Heartbeat Tick: 1
Election Tick: 3
Dispatcher:
Heartbeat Period: 30 seconds
CA Configuration:
Expiry Duration: 3 months
Node Address:
Runtimes: runc
Default Runtime: runc
Security Options: apparmor seccomp
Kernel Version: 4.4.0-47-generic
Operating System: Ubuntu 16.04.1 LTS
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 13.69 GiB
Name: Server1
ID: (obfuscated)
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
File Descriptors: 40
Goroutines: 152
System Time: 2016-11-25T14:12:02.859819248Z
EventsListeners: 0
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Insecure Registries:
127.0.0.0/8

Docker info server 2

docker info
Containers: 0
Running: 0
Paused: 0
Stopped: 0
Images: 34
Server Version: 1.12.3
Storage Driver: aufs
Root Dir: /var/lib/docker/aufs
Backing Filesystem: extfs
Dirs: 41
Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host overlay null
Swarm: active
NodeID: 7ctk1amoja3tunmmpu4ub2o2x
Error: rpc error: code = 4 desc = context deadline exceeded
Is Manager: true
ClusterID:
Managers: 0
Nodes: 0
Orchestration:
Task History Retention Limit: 0
Raft:
Snapshot Interval: 0
Heartbeat Tick: 0
Election Tick: 0
Dispatcher:
Heartbeat Period: Less than a second
CA Configuration:
Expiry Duration: Less than a second
Node Address:
Runtimes: runc
Default Runtime: runc
Security Options: apparmor seccomp
Kernel Version: 4.4.0-47-generic
Operating System: Ubuntu 16.04.1 LTS
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 13.69 GiB
Name: Server2
ID: (obfuscated)
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Insecure Registries:
127.0.0.0/8

To set this up, I opened up the following ports between machines:

Tcp 2376 docker engine TLS
Tcp 3376 docker swarm TLS
Tcp 2377 docker swarm join
Tcp/Udp 7946 docker swarm synchronisation
Tcp/Udp 4789 docker swarm overlay networking

I then set up the swarm like this:

On Server 1

docker swarm init --listen-addr eth0 --advertise-addr

On Server 2

docker swarm join --listen-addr eth0 --advertise-addr <server 2 public ip address> --token :2377

After a period of time, when you run a command like this on server 2

docker node ls

you get the following errors in the log on server 2:

Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.841641549Z" level=info msg="Waiting for TLS certificate to be issued..."
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.865012702Z" level=info msg="Downloaded new TLS credentials with role: swarm-manager."
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.878731433Z" level=info msg="Listening for connections" addr="10.3.1.5:2377" proto=tcp
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.878741833Z" level=info msg="Listening for local connections" addr="/var/lib/docker/swarm/control.sock" proto=unix
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.926094940Z" level=info msg="73f7d8b896ff9025 became follower at term 0"
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.926376540Z" level=info msg="newRaft 73f7d8b896ff9025 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.926630941Z" level=info msg="73f7d8b896ff9025 became follower at term 1"
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.934524559Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=10.3.1.5 Local-addr=10.3.1.5 Adv-addr= Remote-addr ="
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.943576379Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=10.3.1.5 Local-addr=10.3.1.5 Adv-addr= Remote-addr ="
Nov 25 12:19:17 server2 dockerd[14235]: time="2016-11-25T12:19:17.943882980Z" level=info msg="Gossip cluster hostname server2-c9c8a253961d"
Nov 25 12:19:18 server2 dockerd[14235]: time="2016-11-25T12:19:18.796246903Z" level=info msg="73f7d8b896ff9025 [term: 1] received a MsgHeartbeat message with higher term from 405d674cfc13c3a5 [term: 2]"
Nov 25 12:19:18 server2 dockerd[14235]: time="2016-11-25T12:19:18.796375204Z" level=info msg="73f7d8b896ff9025 became follower at term 2"
Nov 25 12:19:18 server2 dockerd[14235]: time="2016-11-25T12:19:18.796397304Z" level=info msg="raft.node: 73f7d8b896ff9025 elected leader 405d674cfc13c3a5 at term 2"
Nov 25 12:19:18 server2 dockerd[14235]: time="2016-11-25T12:19:18Z" level=info msg="Firewalld running: false"
Nov 25 12:30:21 server2 dockerd[14235]: time="2016-11-25T12:30:21.864295987Z" level=error msg="Error getting nodes: rpc error: code = 4 desc = context deadline exceeded"
Nov 25 12:30:21 server2 dockerd[14235]: time="2016-11-25T12:30:21.864858388Z" level=error msg="Handler for GET /v1.24/nodes returned error: rpc error: code = 4 desc = context deadline exceeded"

Here’s the log from server 1:

Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.739091644Z" level=debug msg="Calling POST /v1.24/swarm/init"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.739726072Z" level=debug msg="form data: {"AdvertiseAddr":"","ForceNewCluster":false,"ListenAddr":"eth0:2377","Spec":{"CAConfig":{"NodeCertExpiry":7.776e+15},"Dispatcher":{"HeartbeatPeriod":3e+10},"Orchestration":{"TaskHistoryRetentionLimit":5},"Raft":{},"TaskDefaults":{}}}"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.781763477Z" level=debug msg="successfully loaded the Root CA: /var/lib/docker/swarm/certificates/swarm-root-ca.crt"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.783102838Z" level=debug msg="successfully loaded the Root CA: /var/lib/docker/swarm/certificates/swarm-root-ca.crt"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.783138440Z" level=debug msg="loaded local CA certificate: /var/lib/docker/swarm/certificates/swarm-root-ca.crt."
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.783914475Z" level=debug msg="loaded local TLS credentials: /var/lib/docker/swarm/certificates/swarm-node.crt."
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.784090283Z" level=debug msg="Requesting certificate for NodeID: clcle3y7pisfitqz9ni5dp6fj"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.792411260Z" level=debug msg="successfully loaded the Root CA: /var/lib/docker/swarm/certificates/swarm-root-ca.crt"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.794809368Z" level=info msg="Listening for connections" addr="10.3.1.4:2377" proto=tcp
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.795240388Z" level=info msg="Listening for local connections" addr="/var/lib/docker/swarm/control.sock" proto=unix
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.802526118Z" level=info msg="405d674cfc13c3a5 became follower at term 0"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.802621522Z" level=info msg="newRaft 405d674cfc13c3a5 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.802671425Z" level=info msg="405d674cfc13c3a5 became follower at term 1"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.802836632Z" level=info msg="405d674cfc13c3a5 is starting a new election at term 1"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.802899735Z" level=info msg="405d674cfc13c3a5 became candidate at term 2"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.803004840Z" level=info msg="405d674cfc13c3a5 received vote from 405d674cfc13c3a5 at term 2"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.803040041Z" level=info msg="405d674cfc13c3a5 became leader at term 2"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.803055942Z" level=info msg="raft.node: 405d674cfc13c3a5 elected leader 405d674cfc13c3a5 at term 2"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.810146563Z" level=debug msg="(*Agent).run" module=agent
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.810751291Z" level=debug msg="(*session).start" module=agent
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.860177230Z" level=debug msg="Root CA updated successfully" cluster.id=5qvbbpps63z4i2i0w7cpnlj1u method="(*Server).updateCluster" module=ca
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.867436659Z" level=debug msg="RequestPool(GlobalDefault, 10.255.0.0/16, , map[], false)"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.867499062Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, , map[])"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.881913015Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, , map[])"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.897195107Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, , map[])"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.897216408Z" level=debug msg="(*session).listen" module=agent session.id=7mof2590xsd8ppzdldjuonr3n
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.897443619Z" level=debug msg="(*session).heartbeat" module=agent session.id=7mof2590xsd8ppzdldjuonr3n
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.897483121Z" level=debug msg="(*session).watch" module=agent session.id=7mof2590xsd8ppzdldjuonr3n
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.898467165Z" level=debug method="(*Dispatcher).Tasks" node.id=clcle3y7pisfitqz9ni5dp6fj node.session=7mof2590xsd8ppzdldjuonr3n
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917191614Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=10.3.1.4 Local-addr=10.3.1.4 Adv-addr= Remote-addr ="
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917527229Z" level=debug msg="agent: registered" module=agent
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917572131Z" level=debug msg="(*worker).Assign" len(tasks)=0 module=agent
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917757239Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=10.3.1.4 Local-addr=10.3.1.4 Adv-addr= Remote-addr ="
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917860344Z" level=info msg="Gossip cluster hostname server1-40f049e0a80b"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917899746Z" level=debug msg="Encryption key 1: 7d736"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917922047Z" level=debug msg="Encryption key 2: e36bd"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.917933647Z" level=debug msg="Encryption key 3: e4899"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918329765Z" level=debug msg="Initial encryption keys: [(key: caad4, tag: 0xa456) (key: f9e29, tag: 0xa455) (key: fde37, tag: 0xa457)]"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918421869Z" level=debug msg="Initial encryption keys: [(key: caad4, tag: 0xa456) (key: f9e29, tag: 0xa455) (key: fde37, tag: 0xa457)]"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918559976Z" level=debug msg="Allocating IPv4 pools for network ingress (dmagsvp33s2owv1txmo7y72al)"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918622578Z" level=debug msg="RequestPool(LocalDefault, 10.255.0.0/16, , map[], false)"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918664780Z" level=debug msg="RequestAddress(LocalDefault/10.255.0.0/16, 10.255.0.1, map[RequestAddressType:com.docker.network.gateway])"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918699382Z" level=debug msg="overlay: Received vxlan IDs: 256"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.918744684Z" level=debug msg="/sbin/iptables, [--wait -t mangle -C OUTPUT -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=65536 -j MARK --set-mark 13681891]"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.922047134Z" level=debug msg="server1-40f049e0a80b: joined network dmagsvp33s2owv1txmo7y72al"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.922091236Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server1-40f049e0a80b]"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.922148838Z" level=debug msg="/sbin/iptables, [--wait -t filter -L DOCKER-INGRESS]"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.937591838Z" level=debug msg="Root CA updated successfully" cluster.id=5qvbbpps63z4i2i0w7cpnlj1u method="(*Server).updateCluster" module=ca
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.938845795Z" level=debug msg="Calling GET /v1.24/swarm"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.940258959Z" level=debug msg="Calling GET /v1.24/nodes/clcle3y7pisfitqz9ni5dp6fj"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.963203498Z" level=debug msg="Assigning addresses for endpoint ingress-endpoint's interface on network ingress"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.963256801Z" level=debug msg="RequestAddress(LocalDefault/10.255.0.0/16, 10.255.0.3, map[])"
Nov 25 12:18:10 server1 dockerd[14697]: time="2016-11-25T12:18:10.973256854Z" level=debug msg="Assigning addresses for endpoint ingress-endpoint's interface on network ingress"
Nov 25 12:18:11 server1 dockerd[14697]: time="2016-11-25T12:18:11.101928184Z" level=debug msg="checkEncryption(dmagsvp, , 256, true)"
Nov 25 12:18:11 server1 dockerd[14697]: time="2016-11-25T12:18:11Z" level=info msg="Firewalld running: false"
Nov 25 12:18:11 server1 dockerd[14697]: time="2016-11-25T12:18:11.203661394Z" level=debug msg="Assigning addresses for endpoint gateway_ingress-sbox's interface on network docker_gwbridge"
Nov 25 12:18:11 server1 dockerd[14697]: time="2016-11-25T12:18:11.203714796Z" level=debug msg="RequestAddress(LocalDefault/172.18.0.0/16, , map[])"
Nov 25 12:18:11 server1 dockerd[14697]: time="2016-11-25T12:18:11.214685693Z" level=debug msg="Assigning addresses for endpoint gateway_ingress-sbox's interface on network docker_gwbridge"
Nov 25 12:18:11 server1 dockerd[14697]: time="2016-11-25T12:18:11.289262372Z" level=debug msg="Programming external connectivity on endpoint gateway_ingress-sbox (6ea60d464f36e459c6cba4082812004333025b3023b85a34bfed4650cb780f91)"
Nov 25 12:18:22 server1 dockerd[14697]: time="2016-11-25T12:18:22.097358694Z" level=debug msg="Calling GET /v1.24/swarm"
Nov 25 12:18:22 server1 dockerd[14697]: time="2016-11-25T12:18:22.099086373Z" level=debug msg="Calling GET /v1.24/info"
Nov 25 12:18:22 server1 dockerd[14697]: time="2016-11-25T12:18:22.138071539Z" level=debug msg="Calling GET /v1.24/swarm"
Nov 25 12:18:22 server1 dockerd[14697]: time="2016-11-25T12:18:22.139383599Z" level=debug msg="Calling GET /v1.24/nodes/clcle3y7pisfitqz9ni5dp6fj"
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.840036608Z" level=debug msg="new certificate entry added" method=IssueNodeCertificate node.id=7ctk1amoja3tunmmpu4ub2o2x node.role=MANAGER
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.840210816Z" level=debug msg="global orchestrator: node 7ctk1amoja3tunmmpu4ub2o2x not in current node list, adding it"
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.840279519Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, , map[])"
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.850754393Z" level=debug msg="started watching for certificate updates" method=NodeCertificateStatus node.id=7ctk1amoja3tunmmpu4ub2o2x status={PENDING }
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.862538027Z" level=debug msg="certificate issued" method="(*Server).signNodeCert" module=ca node.id=7ctk1amoja3tunmmpu4ub2o2x node.role=MANAGER
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.872587083Z" level=debug msg="certificate issued" method="(*Server).signNodeCert" module=ca node.id=7ctk1amoja3tunmmpu4ub2o2x node.role=MANAGER
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.906084901Z" level=debug method="(*Dispatcher).Tasks" node.id=7ctk1amoja3tunmmpu4ub2o2x node.session=8deyqv5fh9xrtgnotusw952wz
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.912543793Z" level=debug msg="node joined" method="(*Node).Join" node.id=7ctk1amoja3tunmmpu4ub2o2x
Nov 25 12:19:17 server1 dockerd[14697]: time="2016-11-25T12:19:17.945217674Z" level=debug msg="2016/11/25 12:19:17 [DEBUG] memberlist: TCP connection from=:52484\n"
Nov 25 12:19:18 server1 dockerd[14697]: time="2016-11-25T12:19:18.748812787Z" level=debug msg="2016/11/25 12:19:18 [DEBUG] memberlist: TCP connection from=:52486\n"
Nov 25 12:19:18 server1 dockerd[14697]: time="2016-11-25T12:19:18.751445807Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:19:18 server1 dockerd[14697]: time="2016-11-25T12:19:18.819484390Z" level=debug msg="405d674cfc13c3a5 received msgApp rejection(lastindex: 0) from 73f7d8b896ff9025 for index 18"
Nov 25 12:19:18 server1 dockerd[14697]: time="2016-11-25T12:19:18.819544192Z" level=debug msg="405d674cfc13c3a5 decreased progress of 73f7d8b896ff9025 to [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]"
Nov 25 12:19:19 server1 dockerd[14697]: time="2016-11-25T12:19:19.144977939Z" level=debug msg="checkEncryption(dmagsvp, , 256, false)"
Nov 25 12:19:19 server1 dockerd[14697]: time="2016-11-25T12:19:19.145355056Z" level=debug msg="miss notification for dest IP, 10.255.0.4"
Nov 25 12:19:28 server1 dockerd[14697]: time="2016-11-25T12:19:28.574516022Z" level=debug msg="Calling GET /v1.24/nodes"
Nov 25 12:19:28 server1 dockerd[14697]: time="2016-11-25T12:19:28.576367006Z" level=debug msg="Calling GET /v1.24/info"
Nov 25 12:19:32 server1 dockerd[14697]: time="2016-11-25T12:19:32.287941891Z" level=debug msg="2016/11/25 12:19:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:19:40 server1 dockerd[14697]: time="2016-11-25T12:19:40.918429371Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:19:40 server1 dockerd[14697]: time="2016-11-25T12:19:40.918929994Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:19:40 server1 dockerd[14697]: time="2016-11-25T12:19:40.922562258Z" level=debug msg="2016/11/25 12:19:40 [DEBUG] memberlist: TCP connection from=:52500\n"
Nov 25 12:19:40 server1 dockerd[14697]: time="2016-11-25T12:19:40.922808969Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.133097ms"
Nov 25 12:19:47 server1 dockerd[14697]: time="2016-11-25T12:19:47.945412592Z" level=debug msg="2016/11/25 12:19:47 [DEBUG] memberlist: TCP connection from=:52502\n"
Nov 25 12:19:47 server1 dockerd[14697]: time="2016-11-25T12:19:47.945745707Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:20:02 server1 dockerd[14697]: time="2016-11-25T12:20:02.291186963Z" level=debug msg="2016/11/25 12:20:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:20:10 server1 dockerd[14697]: time="2016-11-25T12:20:10.918423205Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:20:10 server1 dockerd[14697]: time="2016-11-25T12:20:10.919012931Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:20:10 server1 dockerd[14697]: time="2016-11-25T12:20:10.922070170Z" level=debug msg="2016/11/25 12:20:10 [DEBUG] memberlist: TCP connection from=:52512\n"
Nov 25 12:20:10 server1 dockerd[14697]: time="2016-11-25T12:20:10.922630895Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.122196ms"
Nov 25 12:20:17 server1 dockerd[14697]: time="2016-11-25T12:20:17.209458383Z" level=debug msg="2016/11/25 12:20:17 [DEBUG] memberlist: TCP connection from=:52514\n"
Nov 25 12:20:17 server1 dockerd[14697]: time="2016-11-25T12:20:17.945366431Z" level=debug msg="2016/11/25 12:20:17 [DEBUG] memberlist: TCP connection from=:52516\n"
Nov 25 12:20:17 server1 dockerd[14697]: time="2016-11-25T12:20:17.946055462Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:20:32 server1 dockerd[14697]: time="2016-11-25T12:20:32.294613874Z" level=debug msg="2016/11/25 12:20:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:20:40 server1 dockerd[14697]: time="2016-11-25T12:20:40.918476671Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:20:40 server1 dockerd[14697]: time="2016-11-25T12:20:40.918533074Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:20:40 server1 dockerd[14697]: time="2016-11-25T12:20:40.921808622Z" level=debug msg="2016/11/25 12:20:40 [DEBUG] memberlist: TCP connection from=:52526\n"
Nov 25 12:20:40 server1 dockerd[14697]: time="2016-11-25T12:20:40.922310045Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.298704ms"
Nov 25 12:20:47 server1 dockerd[14697]: time="2016-11-25T12:20:47.212366585Z" level=debug msg="2016/11/25 12:20:47 [DEBUG] memberlist: TCP connection from=:52536\n"
Nov 25 12:20:47 server1 dockerd[14697]: time="2016-11-25T12:20:47.945305799Z" level=debug msg="2016/11/25 12:20:47 [DEBUG] memberlist: TCP connection from=:52538\n"
Nov 25 12:20:47 server1 dockerd[14697]: time="2016-11-25T12:20:47.945918927Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:21:02 server1 dockerd[14697]: time="2016-11-25T12:21:02.298085715Z" level=debug msg="2016/11/25 12:21:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:21:10 server1 dockerd[14697]: time="2016-11-25T12:21:10.918525066Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:21:10 server1 dockerd[14697]: time="2016-11-25T12:21:10.919078191Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:21:10 server1 dockerd[14697]: time="2016-11-25T12:21:10.922171931Z" level=debug msg="2016/11/25 12:21:10 [DEBUG] memberlist: TCP connection from=:52548\n"
Nov 25 12:21:10 server1 dockerd[14697]: time="2016-11-25T12:21:10.922420742Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 1.884986ms"
Nov 25 12:21:17 server1 dockerd[14697]: time="2016-11-25T12:21:17.215611131Z" level=debug msg="2016/11/25 12:21:17 [DEBUG] memberlist: TCP connection from=:52550\n"
Nov 25 12:21:17 server1 dockerd[14697]: time="2016-11-25T12:21:17.945639113Z" level=debug msg="2016/11/25 12:21:17 [DEBUG] memberlist: TCP connection from=:52552\n"
Nov 25 12:21:17 server1 dockerd[14697]: time="2016-11-25T12:21:17.946244641Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:21:32 server1 dockerd[14697]: time="2016-11-25T12:21:32.301161267Z" level=debug msg="2016/11/25 12:21:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:21:40 server1 dockerd[14697]: time="2016-11-25T12:21:40.918570287Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:21:40 server1 dockerd[14697]: time="2016-11-25T12:21:40.918622590Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:21:40 server1 dockerd[14697]: time="2016-11-25T12:21:40.922294156Z" level=debug msg="2016/11/25 12:21:40 [DEBUG] memberlist: TCP connection from=:52562\n"
Nov 25 12:21:40 server1 dockerd[14697]: time="2016-11-25T12:21:40.922604270Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 1.946289ms"
Nov 25 12:21:47 server1 dockerd[14697]: time="2016-11-25T12:21:47.218591391Z" level=debug msg="2016/11/25 12:21:47 [DEBUG] memberlist: TCP connection from=:52564\n"
Nov 25 12:21:47 server1 dockerd[14697]: time="2016-11-25T12:21:47.945464831Z" level=debug msg="2016/11/25 12:21:47 [DEBUG] memberlist: TCP connection from=:52566\n"
Nov 25 12:21:47 server1 dockerd[14697]: time="2016-11-25T12:21:47.946201164Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:22:02 server1 dockerd[14697]: time="2016-11-25T12:22:02.304514856Z" level=debug msg="2016/11/25 12:22:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:22:10 server1 dockerd[14697]: time="2016-11-25T12:22:10.918439126Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:22:10 server1 dockerd[14697]: time="2016-11-25T12:22:10.918542831Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:22:10 server1 dockerd[14697]: time="2016-11-25T12:22:10.921527366Z" level=debug msg="2016/11/25 12:22:10 [DEBUG] memberlist: TCP connection from=:52576\n"
Nov 25 12:22:10 server1 dockerd[14697]: time="2016-11-25T12:22:10.922067390Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.193999ms"
Nov 25 12:22:17 server1 dockerd[14697]: time="2016-11-25T12:22:17.221412668Z" level=debug msg="2016/11/25 12:22:17 [DEBUG] memberlist: TCP connection from=:52578\n"
Nov 25 12:22:17 server1 dockerd[14697]: time="2016-11-25T12:22:17.945165968Z" level=debug msg="2016/11/25 12:22:17 [DEBUG] memberlist: TCP connection from=:52580\n"
Nov 25 12:22:17 server1 dockerd[14697]: time="2016-11-25T12:22:17.945799697Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:22:32 server1 dockerd[14697]: time="2016-11-25T12:22:32.307157138Z" level=debug msg="2016/11/25 12:22:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:22:40 server1 dockerd[14697]: time="2016-11-25T12:22:40.918572501Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:22:40 server1 dockerd[14697]: time="2016-11-25T12:22:40.919050022Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:22:40 server1 dockerd[14697]: time="2016-11-25T12:22:40.922207365Z" level=debug msg="2016/11/25 12:22:40 [DEBUG] memberlist: TCP connection from=:52590\n"
Nov 25 12:22:40 server1 dockerd[14697]: time="2016-11-25T12:22:40.922703388Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.229501ms"
Nov 25 12:22:47 server1 dockerd[14697]: time="2016-11-25T12:22:47.235360274Z" level=debug msg="2016/11/25 12:22:47 [DEBUG] memberlist: TCP connection from=:52592\n"
Nov 25 12:22:47 server1 dockerd[14697]: time="2016-11-25T12:22:47.945085438Z" level=debug msg="2016/11/25 12:22:47 [DEBUG] memberlist: TCP connection from=:52594\n"
Nov 25 12:22:47 server1 dockerd[14697]: time="2016-11-25T12:22:47.945824272Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:23:02 server1 dockerd[14697]: time="2016-11-25T12:23:02.310146858Z" level=debug msg="2016/11/25 12:23:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:23:10 server1 dockerd[14697]: time="2016-11-25T12:23:10.918457187Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:23:10 server1 dockerd[14697]: time="2016-11-25T12:23:10.918966910Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:23:10 server1 dockerd[14697]: time="2016-11-25T12:23:10.922144154Z" level=debug msg="2016/11/25 12:23:10 [DEBUG] memberlist: TCP connection from=:52604\n"
Nov 25 12:23:10 server1 dockerd[14697]: time="2016-11-25T12:23:10.922666577Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.219001ms"
Nov 25 12:23:17 server1 dockerd[14697]: time="2016-11-25T12:23:17.238473811Z" level=debug msg="2016/11/25 12:23:17 [DEBUG] memberlist: TCP connection from=:52614\n"
Nov 25 12:23:17 server1 dockerd[14697]: time="2016-11-25T12:23:17.945121436Z" level=debug msg="2016/11/25 12:23:17 [DEBUG] memberlist: TCP connection from=:52616\n"
Nov 25 12:23:17 server1 dockerd[14697]: time="2016-11-25T12:23:17.945814768Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:23:32 server1 dockerd[14697]: time="2016-11-25T12:23:32.313341510Z" level=debug msg="2016/11/25 12:23:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:23:40 server1 dockerd[14697]: time="2016-11-25T12:23:40.918417397Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:23:40 server1 dockerd[14697]: time="2016-11-25T12:23:40.918473700Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:23:40 server1 dockerd[14697]: time="2016-11-25T12:23:40.921730048Z" level=debug msg="2016/11/25 12:23:40 [DEBUG] memberlist: TCP connection from=:52618\n"
Nov 25 12:23:40 server1 dockerd[14697]: time="2016-11-25T12:23:40.922183068Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.362207ms"
Nov 25 12:23:47 server1 dockerd[14697]: time="2016-11-25T12:23:47.241462563Z" level=debug msg="2016/11/25 12:23:47 [DEBUG] memberlist: TCP connection from=:52628\n"
Nov 25 12:23:47 server1 dockerd[14697]: time="2016-11-25T12:23:47.945062751Z" level=debug msg="2016/11/25 12:23:47 [DEBUG] memberlist: TCP connection from=:52630\n"
Nov 25 12:23:47 server1 dockerd[14697]: time="2016-11-25T12:23:47.945804084Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:24:02 server1 dockerd[14697]: time="2016-11-25T12:24:02.316168165Z" level=debug msg="2016/11/25 12:24:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:24:10 server1 dockerd[14697]: time="2016-11-25T12:24:10.918413630Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:24:10 server1 dockerd[14697]: time="2016-11-25T12:24:10.918975955Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:24:10 server1 dockerd[14697]: time="2016-11-25T12:24:10.921876087Z" level=debug msg="2016/11/25 12:24:10 [DEBUG] memberlist: TCP connection from=:52640\n"
Nov 25 12:24:10 server1 dockerd[14697]: time="2016-11-25T12:24:10.922386310Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 1.99269ms"
Nov 25 12:24:17 server1 dockerd[14697]: time="2016-11-25T12:24:17.244160122Z" level=debug msg="2016/11/25 12:24:17 [DEBUG] memberlist: TCP connection from=:52642\n"
Nov 25 12:24:17 server1 dockerd[14697]: time="2016-11-25T12:24:17.944883180Z" level=debug msg="2016/11/25 12:24:17 [DEBUG] memberlist: TCP connection from=:52644\n"
Nov 25 12:24:17 server1 dockerd[14697]: time="2016-11-25T12:24:17.945688416Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:24:32 server1 dockerd[14697]: time="2016-11-25T12:24:32.325181019Z" level=debug msg="2016/11/25 12:24:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:24:40 server1 dockerd[14697]: time="2016-11-25T12:24:40.918466284Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:24:40 server1 dockerd[14697]: time="2016-11-25T12:24:40.919009208Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:24:40 server1 dockerd[14697]: time="2016-11-25T12:24:40.922134150Z" level=debug msg="2016/11/25 12:24:40 [DEBUG] memberlist: TCP connection from=:52654\n"
Nov 25 12:24:40 server1 dockerd[14697]: time="2016-11-25T12:24:40.922595871Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.177198ms"
Nov 25 12:24:47 server1 dockerd[14697]: time="2016-11-25T12:24:47.246968504Z" level=debug msg="2016/11/25 12:24:47 [DEBUG] memberlist: TCP connection from=:52656\n"
Nov 25 12:24:47 server1 dockerd[14697]: time="2016-11-25T12:24:47.945058343Z" level=debug msg="2016/11/25 12:24:47 [DEBUG] memberlist: TCP connection from=:52658\n"
Nov 25 12:24:47 server1 dockerd[14697]: time="2016-11-25T12:24:47.945819578Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:25:02 server1 dockerd[14697]: time="2016-11-25T12:25:02.328467632Z" level=debug msg="2016/11/25 12:25:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:25:10 server1 dockerd[14697]: time="2016-11-25T12:25:10.918450552Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:25:10 server1 dockerd[14697]: time="2016-11-25T12:25:10.918543656Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:25:10 server1 dockerd[14697]: time="2016-11-25T12:25:10.921544492Z" level=debug msg="2016/11/25 12:25:10 [DEBUG] memberlist: TCP connection from=:52668\n"
Nov 25 12:25:10 server1 dockerd[14697]: time="2016-11-25T12:25:10.922037715Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.179199ms"
Nov 25 12:25:17 server1 dockerd[14697]: time="2016-11-25T12:25:17.250365931Z" level=debug msg="2016/11/25 12:25:17 [DEBUG] memberlist: TCP connection from=:52670\n"
Nov 25 12:25:17 server1 dockerd[14697]: time="2016-11-25T12:25:17.945281127Z" level=debug msg="2016/11/25 12:25:17 [DEBUG] memberlist: TCP connection from=:52672\n"
Nov 25 12:25:17 server1 dockerd[14697]: time="2016-11-25T12:25:17.945931156Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:25:32 server1 dockerd[14697]: time="2016-11-25T12:25:32.331112734Z" level=debug msg="2016/11/25 12:25:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:25:40 server1 dockerd[14697]: time="2016-11-25T12:25:40.918571344Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:25:40 server1 dockerd[14697]: time="2016-11-25T12:25:40.919166971Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:25:40 server1 dockerd[14697]: time="2016-11-25T12:25:40.922588626Z" level=debug msg="2016/11/25 12:25:40 [DEBUG] memberlist: TCP connection from=:52682\n"
Nov 25 12:25:40 server1 dockerd[14697]: time="2016-11-25T12:25:40.923184453Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.502613ms"
Nov 25 12:25:47 server1 dockerd[14697]: time="2016-11-25T12:25:47.253547065Z" level=debug msg="2016/11/25 12:25:47 [DEBUG] memberlist: TCP connection from=:52684\n"
Nov 25 12:25:47 server1 dockerd[14697]: time="2016-11-25T12:25:47.945162111Z" level=debug msg="2016/11/25 12:25:47 [DEBUG] memberlist: TCP connection from=:52686\n"
Nov 25 12:25:47 server1 dockerd[14697]: time="2016-11-25T12:25:47.945452524Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:26:02 server1 dockerd[14697]: time="2016-11-25T12:26:02.334430881Z" level=debug msg="2016/11/25 12:26:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:26:10 server1 dockerd[14697]: time="2016-11-25T12:26:10.918476941Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:26:10 server1 dockerd[14697]: time="2016-11-25T12:26:10.918919661Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:26:10 server1 dockerd[14697]: time="2016-11-25T12:26:10.922449421Z" level=debug msg="2016/11/25 12:26:10 [DEBUG] memberlist: TCP connection from=:52696\n"
Nov 25 12:26:10 server1 dockerd[14697]: time="2016-11-25T12:26:10.922987346Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.577617ms"
Nov 25 12:26:17 server1 dockerd[14697]: time="2016-11-25T12:26:17.256603009Z" level=debug msg="2016/11/25 12:26:17 [DEBUG] memberlist: TCP connection from=:52706\n"
Nov 25 12:26:17 server1 dockerd[14697]: time="2016-11-25T12:26:17.945059312Z" level=debug msg="2016/11/25 12:26:17 [DEBUG] memberlist: TCP connection from=:52708\n"
Nov 25 12:26:17 server1 dockerd[14697]: time="2016-11-25T12:26:17.945366126Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:26:32 server1 dockerd[14697]: time="2016-11-25T12:26:32.337196054Z" level=debug msg="2016/11/25 12:26:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:26:40 server1 dockerd[14697]: time="2016-11-25T12:26:40.918458165Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:26:40 server1 dockerd[14697]: time="2016-11-25T12:26:40.918516068Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:26:40 server1 dockerd[14697]: time="2016-11-25T12:26:40.921910925Z" level=debug msg="2016/11/25 12:26:40 [DEBUG] memberlist: TCP connection from=:52718\n"
Nov 25 12:26:40 server1 dockerd[14697]: time="2016-11-25T12:26:40.922415149Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.611521ms"
Nov 25 12:26:47 server1 dockerd[14697]: time="2016-11-25T12:26:47.259477744Z" level=debug msg="2016/11/25 12:26:47 [DEBUG] memberlist: TCP connection from=:52720\n"
Nov 25 12:26:47 server1 dockerd[14697]: time="2016-11-25T12:26:47.945114216Z" level=debug msg="2016/11/25 12:26:47 [DEBUG] memberlist: TCP connection from=:52722\n"
Nov 25 12:26:47 server1 dockerd[14697]: time="2016-11-25T12:26:47.945797048Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:27:02 server1 dockerd[14697]: time="2016-11-25T12:27:02.341296053Z" level=debug msg="2016/11/25 12:27:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:27:10 server1 dockerd[14697]: time="2016-11-25T12:27:10.918690362Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:27:10 server1 dockerd[14697]: time="2016-11-25T12:27:10.919834915Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:27:10 server1 dockerd[14697]: time="2016-11-25T12:27:10.929622168Z" level=debug msg="2016/11/25 12:27:10 [DEBUG] memberlist: TCP connection from=:52732\n"
Nov 25 12:27:10 server1 dockerd[14697]: time="2016-11-25T12:27:10.930570112Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 4.244497ms"
Nov 25 12:27:17 server1 dockerd[14697]: time="2016-11-25T12:27:17.262472060Z" level=debug msg="2016/11/25 12:27:17 [DEBUG] memberlist: TCP connection from=:52734\n"
Nov 25 12:27:17 server1 dockerd[14697]: time="2016-11-25T12:27:17.945160263Z" level=debug msg="2016/11/25 12:27:17 [DEBUG] memberlist: TCP connection from=:52736\n"
Nov 25 12:27:17 server1 dockerd[14697]: time="2016-11-25T12:27:17.945458477Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:27:32 server1 dockerd[14697]: time="2016-11-25T12:27:32.344641269Z" level=debug msg="2016/11/25 12:27:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:27:40 server1 dockerd[14697]: time="2016-11-25T12:27:40.918633423Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:27:40 server1 dockerd[14697]: time="2016-11-25T12:27:40.918733128Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:27:40 server1 dockerd[14697]: time="2016-11-25T12:27:40.922021280Z" level=debug msg="2016/11/25 12:27:40 [DEBUG] memberlist: TCP connection from=:52746\n"
Nov 25 12:27:40 server1 dockerd[14697]: time="2016-11-25T12:27:40.922306593Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.167101ms"
Nov 25 12:27:47 server1 dockerd[14697]: time="2016-11-25T12:27:47.264823243Z" level=debug msg="2016/11/25 12:27:47 [DEBUG] memberlist: TCP connection from=:52748\n"
Nov 25 12:27:47 server1 dockerd[14697]: time="2016-11-25T12:27:47.945062402Z" level=debug msg="2016/11/25 12:27:47 [DEBUG] memberlist: TCP connection from=:52750\n"
Nov 25 12:27:47 server1 dockerd[14697]: time="2016-11-25T12:27:47.945394817Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:28:02 server1 dockerd[14697]: time="2016-11-25T12:28:02.348112930Z" level=debug msg="2016/11/25 12:28:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:28:10 server1 dockerd[14697]: time="2016-11-25T12:28:10.918607549Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:28:10 server1 dockerd[14697]: time="2016-11-25T12:28:10.918661351Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:28:10 server1 dockerd[14697]: time="2016-11-25T12:28:10.921765995Z" level=debug msg="2016/11/25 12:28:10 [DEBUG] memberlist: TCP connection from=:52760\n"
Nov 25 12:28:10 server1 dockerd[14697]: time="2016-11-25T12:28:10.922288219Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.198201ms"
Nov 25 12:28:17 server1 dockerd[14697]: time="2016-11-25T12:28:17.268056546Z" level=debug msg="2016/11/25 12:28:17 [DEBUG] memberlist: TCP connection from=:52762\n"
Nov 25 12:28:17 server1 dockerd[14697]: time="2016-11-25T12:28:17.945027825Z" level=debug msg="2016/11/25 12:28:17 [DEBUG] memberlist: TCP connection from=:52764\n"
Nov 25 12:28:17 server1 dockerd[14697]: time="2016-11-25T12:28:17.945693655Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:28:32 server1 dockerd[14697]: time="2016-11-25T12:28:32.350941879Z" level=debug msg="2016/11/25 12:28:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:28:40 server1 dockerd[14697]: time="2016-11-25T12:28:40.918558712Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:28:40 server1 dockerd[14697]: time="2016-11-25T12:28:40.919159039Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:28:40 server1 dockerd[14697]: time="2016-11-25T12:28:40.922949014Z" level=debug msg="2016/11/25 12:28:40 [DEBUG] memberlist: TCP connection from=:52774\n"
Nov 25 12:28:40 server1 dockerd[14697]: time="2016-11-25T12:28:40.923442437Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.911835ms"
Nov 25 12:28:47 server1 dockerd[14697]: time="2016-11-25T12:28:47.271142396Z" level=debug msg="2016/11/25 12:28:47 [DEBUG] memberlist: TCP connection from=:52784\n"
Nov 25 12:28:47 server1 dockerd[14697]: time="2016-11-25T12:28:47.945181612Z" level=debug msg="2016/11/25 12:28:47 [DEBUG] memberlist: TCP connection from=:52786\n"
Nov 25 12:28:47 server1 dockerd[14697]: time="2016-11-25T12:28:47.945828442Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:29:02 server1 dockerd[14697]: time="2016-11-25T12:29:02.354214539Z" level=debug msg="2016/11/25 12:29:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:29:10 server1 dockerd[14697]: time="2016-11-25T12:29:10.918593689Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:29:10 server1 dockerd[14697]: time="2016-11-25T12:29:10.919190217Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:29:10 server1 dockerd[14697]: time="2016-11-25T12:29:10.922603674Z" level=debug msg="2016/11/25 12:29:10 [DEBUG] memberlist: TCP connection from=:52788\n"
Nov 25 12:29:10 server1 dockerd[14697]: time="2016-11-25T12:29:10.923162100Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.362709ms"
Nov 25 12:29:17 server1 dockerd[14697]: time="2016-11-25T12:29:17.274389279Z" level=debug msg="2016/11/25 12:29:17 [DEBUG] memberlist: TCP connection from=:52798\n"
Nov 25 12:29:17 server1 dockerd[14697]: time="2016-11-25T12:29:17.944861205Z" level=debug msg="2016/11/25 12:29:17 [DEBUG] memberlist: TCP connection from=:52800\n"
Nov 25 12:29:17 server1 dockerd[14697]: time="2016-11-25T12:29:17.945363628Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:29:32 server1 dockerd[14697]: time="2016-11-25T12:29:32.357507659Z" level=debug msg="2016/11/25 12:29:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:29:40 server1 dockerd[14697]: time="2016-11-25T12:29:40.918520140Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:29:40 server1 dockerd[14697]: time="2016-11-25T12:29:40.918609945Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:29:40 server1 dockerd[14697]: time="2016-11-25T12:29:40.922178809Z" level=debug msg="2016/11/25 12:29:40 [DEBUG] memberlist: TCP connection from=:52810\n"
Nov 25 12:29:40 server1 dockerd[14697]: time="2016-11-25T12:29:40.922712534Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.705624ms"
Nov 25 12:29:47 server1 dockerd[14697]: time="2016-11-25T12:29:47.277678156Z" level=debug msg="2016/11/25 12:29:47 [DEBUG] memberlist: TCP connection from=:52812\n"
Nov 25 12:29:47 server1 dockerd[14697]: time="2016-11-25T12:29:47.945052215Z" level=debug msg="2016/11/25 12:29:47 [DEBUG] memberlist: TCP connection from=:52814\n"
Nov 25 12:29:47 server1 dockerd[14697]: time="2016-11-25T12:29:47.945837051Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:30:02 server1 dockerd[14697]: time="2016-11-25T12:30:02.360106371Z" level=debug msg="2016/11/25 12:30:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:30:04 server1 dockerd[14697]: time="2016-11-25T12:30:04.704441077Z" level=debug msg="Calling GET /v1.24/nodes"
Nov 25 12:30:04 server1 dockerd[14697]: time="2016-11-25T12:30:04.706696481Z" level=debug msg="Calling GET /v1.24/info"
Nov 25 12:30:10 server1 dockerd[14697]: time="2016-11-25T12:30:10.918440434Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:30:10 server1 dockerd[14697]: time="2016-11-25T12:30:10.919082163Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:30:10 server1 dockerd[14697]: time="2016-11-25T12:30:10.922429717Z" level=debug msg="2016/11/25 12:30:10 [DEBUG] memberlist: TCP connection from=:52824\n"
Nov 25 12:30:10 server1 dockerd[14697]: time="2016-11-25T12:30:10.923014444Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.322007ms"
Nov 25 12:30:17 server1 dockerd[14697]: time="2016-11-25T12:30:17.280926686Z" level=debug msg="2016/11/25 12:30:17 [DEBUG] memberlist: TCP connection from=:52826\n"
Nov 25 12:30:17 server1 dockerd[14697]: time="2016-11-25T12:30:17.944924967Z" level=debug msg="2016/11/25 12:30:17 [DEBUG] memberlist: TCP connection from=:52828\n"
Nov 25 12:30:17 server1 dockerd[14697]: time="2016-11-25T12:30:17.945177278Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:30:32 server1 dockerd[14697]: time="2016-11-25T12:30:32.363196691Z" level=debug msg="2016/11/25 12:30:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:30:40 server1 dockerd[14697]: time="2016-11-25T12:30:40.918391131Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:30:40 server1 dockerd[14697]: time="2016-11-25T12:30:40.918454734Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:30:40 server1 dockerd[14697]: time="2016-11-25T12:30:40.921531075Z" level=debug msg="2016/11/25 12:30:40 [DEBUG] memberlist: TCP connection from=:52838\n"
Nov 25 12:30:40 server1 dockerd[14697]: time="2016-11-25T12:30:40.921976396Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.229102ms"
Nov 25 12:30:47 server1 dockerd[14697]: time="2016-11-25T12:30:47.283971521Z" level=debug msg="2016/11/25 12:30:47 [DEBUG] memberlist: TCP connection from=:52840\n"
Nov 25 12:30:47 server1 dockerd[14697]: time="2016-11-25T12:30:47.945381662Z" level=debug msg="2016/11/25 12:30:47 [DEBUG] memberlist: TCP connection from=:52842\n"
Nov 25 12:30:47 server1 dockerd[14697]: time="2016-11-25T12:30:47.945649874Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:31:02 server1 dockerd[14697]: time="2016-11-25T12:31:02.366328456Z" level=debug msg="2016/11/25 12:31:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:31:10 server1 dockerd[14697]: time="2016-11-25T12:31:10.918459993Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:31:10 server1 dockerd[14697]: time="2016-11-25T12:31:10.918515295Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:31:10 server1 dockerd[14697]: time="2016-11-25T12:31:10.921456531Z" level=debug msg="2016/11/25 12:31:10 [DEBUG] memberlist: TCP connection from=:52852\n"
Nov 25 12:31:10 server1 dockerd[14697]: time="2016-11-25T12:31:10.921751344Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 1.980591ms"
Nov 25 12:31:17 server1 dockerd[14697]: time="2016-11-25T12:31:17.286398799Z" level=debug msg="2016/11/25 12:31:17 [DEBUG] memberlist: TCP connection from=:52854\n"
Nov 25 12:31:17 server1 dockerd[14697]: time="2016-11-25T12:31:17.945002091Z" level=debug msg="2016/11/25 12:31:17 [DEBUG] memberlist: TCP connection from=:52856\n"
Nov 25 12:31:17 server1 dockerd[14697]: time="2016-11-25T12:31:17.945275904Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:31:32 server1 dockerd[14697]: time="2016-11-25T12:31:32.368862992Z" level=debug msg="2016/11/25 12:31:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:31:40 server1 dockerd[14697]: time="2016-11-25T12:31:40.918428463Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:31:40 server1 dockerd[14697]: time="2016-11-25T12:31:40.918491766Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:31:40 server1 dockerd[14697]: time="2016-11-25T12:31:40.921862421Z" level=debug msg="2016/11/25 12:31:40 [DEBUG] memberlist: TCP connection from=:52866\n"
Nov 25 12:31:40 server1 dockerd[14697]: time="2016-11-25T12:31:40.922350143Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.301806ms"
Nov 25 12:31:47 server1 dockerd[14697]: time="2016-11-25T12:31:47.289154816Z" level=debug msg="2016/11/25 12:31:47 [DEBUG] memberlist: TCP connection from=:52876\n"
Nov 25 12:31:47 server1 dockerd[14697]: time="2016-11-25T12:31:47.945426882Z" level=debug msg="2016/11/25 12:31:47 [DEBUG] memberlist: TCP connection from=:52878\n"
Nov 25 12:31:47 server1 dockerd[14697]: time="2016-11-25T12:31:47.945995908Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:32:02 server1 dockerd[14697]: time="2016-11-25T12:32:02.372299219Z" level=debug msg="2016/11/25 12:32:02 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:32:10 server1 dockerd[14697]: time="2016-11-25T12:32:10.918458600Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:32:10 server1 dockerd[14697]: time="2016-11-25T12:32:10.919087829Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:32:10 server1 dockerd[14697]: time="2016-11-25T12:32:10.922152070Z" level=debug msg="2016/11/25 12:32:10 [DEBUG] memberlist: TCP connection from=:52888\n"
Nov 25 12:32:10 server1 dockerd[14697]: time="2016-11-25T12:32:10.922615791Z" level=debug msg="server1-40f049e0a80b: Bulk sync to node server2-c9c8a253961d took 2.133298ms"
Nov 25 12:32:17 server1 dockerd[14697]: time="2016-11-25T12:32:17.291759200Z" level=debug msg="2016/11/25 12:32:17 [DEBUG] memberlist: TCP connection from=:52890\n"
Nov 25 12:32:17 server1 dockerd[14697]: time="2016-11-25T12:32:17.945130515Z" level=debug msg="2016/11/25 12:32:17 [DEBUG] memberlist: TCP connection from=:52892\n"
Nov 25 12:32:17 server1 dockerd[14697]: time="2016-11-25T12:32:17.945482631Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:32:32 server1 dockerd[14697]: time="2016-11-25T12:32:32.375241121Z" level=debug msg="2016/11/25 12:32:32 [DEBUG] memberlist: Initiating push/pull sync with: :7946\n"
Nov 25 12:32:40 server1 dockerd[14697]: time="2016-11-25T12:32:40.918590452Z" level=debug msg="server1-40f049e0a80b: Initiating bulk sync with nodes [server2-c9c8a253961d]"
Nov 25 12:32:40 server1 dockerd[14697]: time="2016-11-25T12:32:40.919164779Z" level=debug msg="server1-40f049e0a80b: Initiating unsolicited bulk sync for networks [dmagsvp33s2owv1txmo7y72al] with node server2-c9c8a253961d"
Nov 25 12:32:40 server1 dockerd[14697]: time="2016-11-25T12:32:40.922603337Z" level=debug msg="2016/11/25 12:32:40 [DEBUG] memberlist: TCP connection from=:52902\n"

Some things I have tried or noted.

  1. I tried the same thing on azure with machines on the same Vlan using the internal ip addresses, then it works fine and I don’t get the issue.

  2. I don’t get the issue if I run a script to continuously call the docker service command like this on server 2.

     while true; do sleep 15; date; docker service ls; done
    
  3. I have also tried with 3 manager nodes to see if this is a raft consensus issue - but both secondary manager nodes get the problem after a while.

  4. if I restart the docker daemon -> sudo systemctl restart docker, then the issue goes away for a period and then it starts getting the error

  5. sometimes the results come back from the ‘docker node ls’ command but they take 30 seconds to 1 minute

  6. I have tried changing the dispatcher heartbeat as follows:

    docker swarm init --listen-addr eth0 --advertise-addr --dispatcher-heartbeat 30s

    this still results in the error

My immediate questions are:

  1. Is there any other ports that I need to open?
  2. Is this a sensible thing to do?
  3. Is there any more logging I can add to get more diagnostics?

I know it’s black friday and you will have much shopping to do, but if you can help, it’ll be much appreciated

thanks
Bart

@aaronlehmann
Copy link
Collaborator

Thanks for the report. I don't see anything obviously wrong with your setup. What I would suspect here is some condition that's causing the current leader to get stuck, so requests to it time out. An example of this kind of problem is #1760, which has a fix in the 1.13 release candidates and will be included in 1.12.4 if such a release comes out.

The best way to help debug this is to send SIGUSR1 to both Docker daemons when you experience the problem. This dumps stack traces to the logs and can help find out if and where a Docker daemon is stuck.

@Bartman250
Copy link
Author

Thanks very much for the response on this.

I'll have a log at the logs when I recreate the situation again - is there anything in particular I should look for - and would you like me to forward them onto you?

thanks
Bart

@aaronlehmann
Copy link
Collaborator

Just the stack trace that gets inserted into the logs. It would be great if you could post it in a GitHub gist or something like that.

@aaronlehmann
Copy link
Collaborator

Hi @Bartman250: Are you still having this problem? If so, are you able to retrieve a stack trace for us to debug with?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants