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

Frequent failure in 110_encryption_test #1042

Closed
awh opened this issue Jun 29, 2015 · 8 comments
Closed

Frequent failure in 110_encryption_test #1042

awh opened this issue Jun 29, 2015 · 8 comments
Assignees
@bboreham
Labels
bug
Milestone
1.0.2

Comments

@awh
Copy link
Contributor

awh commented Jun 29, 2015

@bboreham and @rade report seeing this in addition to myself. Root cause possibly the same as #1030.
@awh awh added the bug label Jun 29, 2015
@bboreham
Copy link
Contributor

I tried raising the count of packets sent by ping to 3, on the hypothesis that it was perhaps losing just the first packet, and subsequent packets would get through. No change; it still fails around 20% of the time.

As part of this exercise, at one point I had two ping commands - one that just printed out what it saw and one that was the original test. In every test I ran, either both succeeded or both failed.

I also tried changing weave launch to weave launch-router, to avoid starting weavedns, but still saw some failures.

@bboreham
Copy link
Contributor

Looking at the logfiles from failed runs, we see that they fail to maintain UDP communication:

Logfile from c2 (with -pktdebug turned on):

INFO: 2015/06/30 10:46:46.636854 Command line options: map[name:2e:ef:1a:56:84:80 nickname:host2 pktdebug:true port:6783 wait:20 iface:ethwe iprange:10.128.0.0/10]
INFO: 2015/06/30 10:46:46.63696 Command line peers: [192.168.48.11]
INFO: 2015/06/30 10:46:46.637117 Communication between peers is encrypted.
INFO: 2015/06/30 10:46:46.637441 Our name is 2e:ef:1a:56:84:80(host2)
INFO: 2015/06/30 10:46:46.63747 Assuming quorum size of 2
INFO: 2015/06/30 10:46:46.638543 [docker] Using Docker API on unix:///var/run/docker.sock: &[Arch=amd64 KernelVersion=3.16.0-37-generic Version=1.7.0 ApiVersion=1.19 GitCommit=0baf609 GoVersion=go1.4.2 Os=linux]
INFO: 2015/06/30 10:46:46.641016 Sniffing traffic on &{906 65535 ethwe de:8a:46:79:fb:85 up|broadcast|multicast}
INFO: 2015/06/30 10:46:46.641285 Discovered our MAC de:8a:46:79:fb:85
INFO: 2015/06/30 10:46:46.642064 ->[192.168.48.11:6783] attempting connection

INFO: 2015/06/30 10:46:46.65136 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: completed handshake; using protocol version 1
INFO: 2015/06/30 10:46:46.651547 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: Effective PMTU set to 65449
INFO: 2015/06/30 10:46:46.651663 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: connection added (new peer)
INFO: 2015/06/30 10:46:46.654795 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: connection fully established
INFO: 2015/06/30 10:46:46.655455 EMSGSIZE on send, expecting PMTU update (IP packet was 60088 bytes, payload was 60080 bytes)
INFO: 2015/06/30 10:46:46.65576 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: Effective PMTU set to 1414
INFO: 2015/06/30 10:46:46.675564 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: Effective PMTU verified at 1414
INFO: 2015/06/30 10:46:47.171249 Sniffed 78 bytes ( 4752eb67b5ad77cb74843d63c6de2ac4f30cc9e9c7eb988ab0cc2e1de121712e )
INFO: 2015/06/30 10:46:47.171285 Discovered local MAC 1a:0d:15:63:91:83
INFO: 2015/06/30 10:46:47.171297 Forwarding 78 bytes ( 4752eb67b5ad77cb74843d63c6de2ac4f30cc9e9c7eb988ab0cc2e1de121712e ) 1a:0d:15:63:91:83 -> 33:33:ff:63:91:83
INFO: 2015/06/30 10:46:47.247213 Sniffed 90 bytes ( 289fa49e062d7db94592db86b6a09f89530f52597a2f5e4b2c0fa7f73618d4c2 )
INFO: 2015/06/30 10:46:47.247303 Forwarding 90 bytes ( 289fa49e062d7db94592db86b6a09f89530f52597a2f5e4b2c0fa7f73618d4c2 ) 1a:0d:15:63:91:83 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:47.479242 Sniffed 90 bytes ( 0c2228111d50532578b895d11fecf040c11239a841519b50b3c4637fd9789625 )
INFO: 2015/06/30 10:46:47.479325 Discovered local MAC 2e:ef:1a:56:84:80
INFO: 2015/06/30 10:46:47.479393 Forwarding 90 bytes ( 0c2228111d50532578b895d11fecf040c11239a841519b50b3c4637fd9789625 ) 2e:ef:1a:56:84:80 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:47.479426 Sniffed 70 bytes ( e1f438000ed9d01d2bed73ea7dcfa206155ce3e15537a6eb9bee3eea88b9cd0d )
INFO: 2015/06/30 10:46:47.479457 Forwarding 70 bytes ( e1f438000ed9d01d2bed73ea7dcfa206155ce3e15537a6eb9bee3eea88b9cd0d ) 2e:ef:1a:56:84:80 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:48.047214 Sniffed 90 bytes ( 0c2228111d50532578b895d11fecf040c11239a841519b50b3c4637fd9789625 )
INFO: 2015/06/30 10:46:48.047303 Forwarding 90 bytes ( 0c2228111d50532578b895d11fecf040c11239a841519b50b3c4637fd9789625 ) 2e:ef:1a:56:84:80 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:48.171245 Sniffed 90 bytes ( 387c4f0fa6c1b75b8d6c849a4a166ea77cb0ace470a86480a7e6cb031a85daf8 )
INFO: 2015/06/30 10:46:48.171339 Forwarding 90 bytes ( 387c4f0fa6c1b75b8d6c849a4a166ea77cb0ace470a86480a7e6cb031a85daf8 ) 1a:0d:15:63:91:83 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:48.171399 Sniffed 70 bytes ( 693f60b62bea0eee6b3710b647045ca0087bbf784c167eb3daaa4961b4728c79 )
INFO: 2015/06/30 10:46:48.171432 Forwarding 70 bytes ( 693f60b62bea0eee6b3710b647045ca0087bbf784c167eb3daaa4961b4728c79 ) 1a:0d:15:63:91:83 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:48.739425 Sniffed 90 bytes ( 387c4f0fa6c1b75b8d6c849a4a166ea77cb0ace470a86480a7e6cb031a85daf8 )
INFO: 2015/06/30 10:46:48.73946 Forwarding 90 bytes ( 387c4f0fa6c1b75b8d6c849a4a166ea77cb0ace470a86480a7e6cb031a85daf8 ) 1a:0d:15:63:91:83 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:49.801579 Sniffed 42 bytes ( cf7a65514c142095813fe22048b46cb770505f175757be88eb40b1c1a0d8eb85 )
INFO: 2015/06/30 10:46:49.802485 Discovered local MAC 5a:06:36:6f:45:cc
INFO: 2015/06/30 10:46:49.802551 Forwarding 42 bytes ( cf7a65514c142095813fe22048b46cb770505f175757be88eb40b1c1a0d8eb85 ) 5a:06:36:6f:45:cc -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:46:49.821109 Sniffed 90 bytes ( 36bb6a7ead0279bd4c328b704b74aaef36452770cecaa340696acc1b8e47c5eb )
INFO: 2015/06/30 10:46:49.821179 Forwarding 90 bytes ( 36bb6a7ead0279bd4c328b704b74aaef36452770cecaa340696acc1b8e47c5eb ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:50.10324 Sniffed 78 bytes ( cb202942932a84d4b3b43d5a1e24b9b01e2a0b7043dd7f1be284e8edc6e9fe3e )
INFO: 2015/06/30 10:46:50.103279 Forwarding 78 bytes ( cb202942932a84d4b3b43d5a1e24b9b01e2a0b7043dd7f1be284e8edc6e9fe3e ) 5a:06:36:6f:45:cc -> 33:33:ff:6f:45:cc
INFO: 2015/06/30 10:46:50.211218 Sniffed 90 bytes ( 36bb6a7ead0279bd4c328b704b74aaef36452770cecaa340696acc1b8e47c5eb )
INFO: 2015/06/30 10:46:50.211263 Forwarding 90 bytes ( 36bb6a7ead0279bd4c328b704b74aaef36452770cecaa340696acc1b8e47c5eb ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:51.103249 Sniffed 90 bytes ( cb27351babd7f2cd0cbebf725ae75ff2b676081e8e211271faad3561900ce5d5 )
INFO: 2015/06/30 10:46:51.103289 Forwarding 90 bytes ( cb27351babd7f2cd0cbebf725ae75ff2b676081e8e211271faad3561900ce5d5 ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:51.103301 Sniffed 70 bytes ( 0783f85f9c5c7906c8ce93b765fa2f7eb20e951156cf360a97947f40dd9a9373 )
INFO: 2015/06/30 10:46:51.103311 Forwarding 70 bytes ( 0783f85f9c5c7906c8ce93b765fa2f7eb20e951156cf360a97947f40dd9a9373 ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:51.399202 Sniffed 90 bytes ( cb27351babd7f2cd0cbebf725ae75ff2b676081e8e211271faad3561900ce5d5 )
INFO: 2015/06/30 10:46:51.399241 Forwarding 90 bytes ( cb27351babd7f2cd0cbebf725ae75ff2b676081e8e211271faad3561900ce5d5 ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:51.48316 Sniffed 70 bytes ( e1f438000ed9d01d2bed73ea7dcfa206155ce3e15537a6eb9bee3eea88b9cd0d )
INFO: 2015/06/30 10:46:51.483213 Forwarding 70 bytes ( e1f438000ed9d01d2bed73ea7dcfa206155ce3e15537a6eb9bee3eea88b9cd0d ) 2e:ef:1a:56:84:80 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:52.179212 Sniffed 70 bytes ( 693f60b62bea0eee6b3710b647045ca0087bbf784c167eb3daaa4961b4728c79 )
INFO: 2015/06/30 10:46:52.179301 Forwarding 70 bytes ( 693f60b62bea0eee6b3710b647045ca0087bbf784c167eb3daaa4961b4728c79 ) 1a:0d:15:63:91:83 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:55.115217 Sniffed 70 bytes ( 0783f85f9c5c7906c8ce93b765fa2f7eb20e951156cf360a97947f40dd9a9373 )
INFO: 2015/06/30 10:46:55.115302 Forwarding 70 bytes ( 0783f85f9c5c7906c8ce93b765fa2f7eb20e951156cf360a97947f40dd9a9373 ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:55.491192 Sniffed 70 bytes ( e1f438000ed9d01d2bed73ea7dcfa206155ce3e15537a6eb9bee3eea88b9cd0d )
INFO: 2015/06/30 10:46:55.49128 Forwarding 70 bytes ( e1f438000ed9d01d2bed73ea7dcfa206155ce3e15537a6eb9bee3eea88b9cd0d ) 2e:ef:1a:56:84:80 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:56.187209 Sniffed 70 bytes ( 693f60b62bea0eee6b3710b647045ca0087bbf784c167eb3daaa4961b4728c79 )
INFO: 2015/06/30 10:46:56.1873 Forwarding 70 bytes ( 693f60b62bea0eee6b3710b647045ca0087bbf784c167eb3daaa4961b4728c79 ) 1a:0d:15:63:91:83 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:59.12322 Sniffed 70 bytes ( 0783f85f9c5c7906c8ce93b765fa2f7eb20e951156cf360a97947f40dd9a9373 )
INFO: 2015/06/30 10:46:59.12331 Forwarding 70 bytes ( 0783f85f9c5c7906c8ce93b765fa2f7eb20e951156cf360a97947f40dd9a9373 ) 5a:06:36:6f:45:cc -> 33:33:00:00:00:02
ERRO: 2015/06/30 10:47:46.652952 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: connection shutting down due to error: timed out waiting for UDP heartbeat
INFO: 2015/06/30 10:47:46.653145 ->[192.168.48.11:6783|aa:6b:ca:a6:30:0b(host1)]: connection deleted
INFO: 2015/06/30 10:47:46.653248 Removed unreachable peer aa:6b:ca:a6:30:0b(host1)

Logfile from c1 from same run as above:

INFO: 2015/06/30 10:46:45.903177 Command line options: map[wait:20 iface:ethwe iprange:10.128.0.0/10 name:aa:6b:ca:a6:30:0b nickname:host1 pktdebug:true port:6783]
INFO: 2015/06/30 10:46:45.903273 Command line peers: []
INFO: 2015/06/30 10:46:45.903427 Communication between peers is encrypted.
INFO: 2015/06/30 10:46:45.903757 Our name is aa:6b:ca:a6:30:0b(host1)
INFO: 2015/06/30 10:46:45.903785 Assuming quorum size of 1
INFO: 2015/06/30 10:46:45.904558 [docker] Using Docker API on unix:///var/run/docker.sock: &[Version=1.7.0 ApiVersion=1.19 GitCommit=0baf609 GoVersion=go1.4.2 Os=linux Arch=amd64 KernelVersion=3.16.0-37-generic]
INFO: 2015/06/30 10:46:45.906862 Sniffing traffic on &{1414 65535 ethwe e6:c3:21:75:04:68 up|broadcast|multicast}
INFO: 2015/06/30 10:46:45.90713 Discovered our MAC e6:c3:21:75:04:68
INFO: 2015/06/30 10:46:46.048887 Sniffed 78 bytes ( 3f4a81741680b4fc16dd196afc954152762ba64496ec1e19adee5ec5031bc4a0 )
INFO: 2015/06/30 10:46:46.048921 Discovered local MAC 5a:7a:24:5e:a5:7f
INFO: 2015/06/30 10:46:46.048933 Forwarding 78 bytes ( 3f4a81741680b4fc16dd196afc954152762ba64496ec1e19adee5ec5031bc4a0 ) 5a:7a:24:5e:a5:7f -> 33:33:ff:5e:a5:7f
INFO: 2015/06/30 10:46:46.180897 Sniffed 78 bytes ( a8ecbbe9beab1112de3d873e0873345c8752c438ad842d4d6d42d559b00cae2b )
INFO: 2015/06/30 10:46:46.180967 Discovered local MAC aa:6b:ca:a6:30:0b
INFO: 2015/06/30 10:46:46.180985 Forwarding 78 bytes ( a8ecbbe9beab1112de3d873e0873345c8752c438ad842d4d6d42d559b00cae2b ) aa:6b:ca:a6:30:0b -> 33:33:ff:a6:30:0b
INFO: 2015/06/30 10:46:46.661427 Sniffed 90 bytes ( 2182eaf7c0f6dfb3cd8c807c550a8b70d8d4c63309401b5d32c4d3de976a5afd )
INFO: 2015/06/30 10:46:46.66153 Forwarding 90 bytes ( 2182eaf7c0f6dfb3cd8c807c550a8b70d8d4c63309401b5d32c4d3de976a5afd ) aa:6b:ca:a6:30:0b -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:47.048854 Sniffed 90 bytes ( f4528e3d4eb869d9891b61bd348bfcbed8cd593afdafbc6e5d2b939c29bdd006 )
INFO: 2015/06/30 10:46:47.048943 Forwarding 90 bytes ( f4528e3d4eb869d9891b61bd348bfcbed8cd593afdafbc6e5d2b939c29bdd006 ) 5a:7a:24:5e:a5:7f -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:47.049005 Sniffed 70 bytes ( 408527f479a425829617001e1de542faea943a774a2b79ab2c1f1b2806b1800f )
INFO: 2015/06/30 10:46:47.049039 Forwarding 70 bytes ( 408527f479a425829617001e1de542faea943a774a2b79ab2c1f1b2806b1800f ) 5a:7a:24:5e:a5:7f -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:47.155079 ->[192.168.48.12:39284] connection accepted

INFO: 2015/06/30 10:46:47.160654 ->[192.168.48.12:39284|2e:ef:1a:56:84:80(host2)]: completed handshake; using protocol version 1
INFO: 2015/06/30 10:46:47.160807 ->[192.168.48.12:39284|2e:ef:1a:56:84:80(host2)]: connection added (new peer)
INFO: 2015/06/30 10:46:47.166135 ->[192.168.48.12:39284|2e:ef:1a:56:84:80(host2)]: Effective PMTU set to 65449
INFO: 2015/06/30 10:46:47.189181 Sniffed 90 bytes ( 0f8b8db9c4f9467207a312e9c1fb09bb1d9ee1252b259c2001071d2383bfcf45 )
INFO: 2015/06/30 10:46:47.189262 Forwarding 90 bytes ( 0f8b8db9c4f9467207a312e9c1fb09bb1d9ee1252b259c2001071d2383bfcf45 ) aa:6b:ca:a6:30:0b -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:47.189338 Sniffed 70 bytes ( 1e1066ff9bd231884c67e645ab3339e91b1a23129904c75de18d55484bcfcbd1 )
INFO: 2015/06/30 10:46:47.189377 Forwarding 70 bytes ( 1e1066ff9bd231884c67e645ab3339e91b1a23129904c75de18d55484bcfcbd1 ) aa:6b:ca:a6:30:0b -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:47.408813 Sniffed 90 bytes ( f4528e3d4eb869d9891b61bd348bfcbed8cd593afdafbc6e5d2b939c29bdd006 )
INFO: 2015/06/30 10:46:47.408903 Forwarding 90 bytes ( f4528e3d4eb869d9891b61bd348bfcbed8cd593afdafbc6e5d2b939c29bdd006 ) 5a:7a:24:5e:a5:7f -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:47.523005 Sniffed 90 bytes ( 0f8b8db9c4f9467207a312e9c1fb09bb1d9ee1252b259c2001071d2383bfcf45 )
INFO: 2015/06/30 10:46:47.523116 Forwarding 90 bytes ( 0f8b8db9c4f9467207a312e9c1fb09bb1d9ee1252b259c2001071d2383bfcf45 ) aa:6b:ca:a6:30:0b -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:48.845708 Sniffed 42 bytes ( e97307f1b7da3ef2f2823cf854cef78cafddacadfd6af0cdbe75e58d6a929230 )
INFO: 2015/06/30 10:46:48.84574 Discovered local MAC c6:15:b5:5b:5a:2c
INFO: 2015/06/30 10:46:48.845754 Forwarding 42 bytes ( e97307f1b7da3ef2f2823cf854cef78cafddacadfd6af0cdbe75e58d6a929230 ) c6:15:b5:5b:5a:2c -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:46:48.85012 Sniffed 90 bytes ( 03c9aea652cd46ad0ab4d9d84f3d2e1c506a21751dd359c8931a98b088cf5f94 )
INFO: 2015/06/30 10:46:48.850155 Forwarding 90 bytes ( 03c9aea652cd46ad0ab4d9d84f3d2e1c506a21751dd359c8931a98b088cf5f94 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:49.613592 Sniffed 90 bytes ( 03c9aea652cd46ad0ab4d9d84f3d2e1c506a21751dd359c8931a98b088cf5f94 )
INFO: 2015/06/30 10:46:49.613634 Forwarding 90 bytes ( 03c9aea652cd46ad0ab4d9d84f3d2e1c506a21751dd359c8931a98b088cf5f94 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:49.640849 Sniffed 78 bytes ( 53ca8f24d26554b1f5cd26ff8075ce9cca4c858440ccf21b1baf96d5f9ad4f95 )
INFO: 2015/06/30 10:46:49.64089 Forwarding 78 bytes ( 53ca8f24d26554b1f5cd26ff8075ce9cca4c858440ccf21b1baf96d5f9ad4f95 ) c6:15:b5:5b:5a:2c -> 33:33:ff:5b:5a:2c
INFO: 2015/06/30 10:46:50.595917 Sniffed 42 bytes ( 7db3fa0c907d143dfcc99d2d437c9823126a72b45dbe7b92883fcaf8f5b14ef4 )
INFO: 2015/06/30 10:46:50.595991 Forwarding 42 bytes ( 7db3fa0c907d143dfcc99d2d437c9823126a72b45dbe7b92883fcaf8f5b14ef4 ) c6:15:b5:5b:5a:2c -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:46:50.640861 Sniffed 90 bytes ( af74fbc473789fd84a8754dfac30bbcd4cad011af898f3c068952101e199f179 )
INFO: 2015/06/30 10:46:50.640953 Forwarding 90 bytes ( af74fbc473789fd84a8754dfac30bbcd4cad011af898f3c068952101e199f179 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:50.641016 Sniffed 70 bytes ( 921c18ea446516e37b807e718c86ca2cc5c187bd038b11f141c78d16ecb20ab1 )
INFO: 2015/06/30 10:46:50.641051 Forwarding 70 bytes ( 921c18ea446516e37b807e718c86ca2cc5c187bd038b11f141c78d16ecb20ab1 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:51.057056 Sniffed 70 bytes ( 408527f479a425829617001e1de542faea943a774a2b79ab2c1f1b2806b1800f )
INFO: 2015/06/30 10:46:51.057145 Forwarding 70 bytes ( 408527f479a425829617001e1de542faea943a774a2b79ab2c1f1b2806b1800f ) 5a:7a:24:5e:a5:7f -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:51.192383 Sniffed 70 bytes ( 1e1066ff9bd231884c67e645ab3339e91b1a23129904c75de18d55484bcfcbd1 )
INFO: 2015/06/30 10:46:51.192464 Forwarding 70 bytes ( 1e1066ff9bd231884c67e645ab3339e91b1a23129904c75de18d55484bcfcbd1 ) aa:6b:ca:a6:30:0b -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:51.37075 Sniffed 90 bytes ( af74fbc473789fd84a8754dfac30bbcd4cad011af898f3c068952101e199f179 )
INFO: 2015/06/30 10:46:51.370846 Forwarding 90 bytes ( af74fbc473789fd84a8754dfac30bbcd4cad011af898f3c068952101e199f179 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:16
INFO: 2015/06/30 10:46:51.591026 Sniffed 42 bytes ( 7db3fa0c907d143dfcc99d2d437c9823126a72b45dbe7b92883fcaf8f5b14ef4 )
INFO: 2015/06/30 10:46:51.591123 Forwarding 42 bytes ( 7db3fa0c907d143dfcc99d2d437c9823126a72b45dbe7b92883fcaf8f5b14ef4 ) c6:15:b5:5b:5a:2c -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:46:52.588943 Sniffed 42 bytes ( 7db3fa0c907d143dfcc99d2d437c9823126a72b45dbe7b92883fcaf8f5b14ef4 )
INFO: 2015/06/30 10:46:52.589055 Forwarding 42 bytes ( 7db3fa0c907d143dfcc99d2d437c9823126a72b45dbe7b92883fcaf8f5b14ef4 ) c6:15:b5:5b:5a:2c -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:46:54.650027 Sniffed 70 bytes ( 921c18ea446516e37b807e718c86ca2cc5c187bd038b11f141c78d16ecb20ab1 )
INFO: 2015/06/30 10:46:54.650116 Forwarding 70 bytes ( 921c18ea446516e37b807e718c86ca2cc5c187bd038b11f141c78d16ecb20ab1 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:55.06444 Sniffed 70 bytes ( 408527f479a425829617001e1de542faea943a774a2b79ab2c1f1b2806b1800f )
INFO: 2015/06/30 10:46:55.064527 Forwarding 70 bytes ( 408527f479a425829617001e1de542faea943a774a2b79ab2c1f1b2806b1800f ) 5a:7a:24:5e:a5:7f -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:55.200367 Sniffed 70 bytes ( 1e1066ff9bd231884c67e645ab3339e91b1a23129904c75de18d55484bcfcbd1 )
INFO: 2015/06/30 10:46:55.200458 Forwarding 70 bytes ( 1e1066ff9bd231884c67e645ab3339e91b1a23129904c75de18d55484bcfcbd1 ) aa:6b:ca:a6:30:0b -> 33:33:00:00:00:02
INFO: 2015/06/30 10:46:58.656703 Sniffed 70 bytes ( 921c18ea446516e37b807e718c86ca2cc5c187bd038b11f141c78d16ecb20ab1 )
INFO: 2015/06/30 10:46:58.656795 Forwarding 70 bytes ( 921c18ea446516e37b807e718c86ca2cc5c187bd038b11f141c78d16ecb20ab1 ) c6:15:b5:5b:5a:2c -> 33:33:00:00:00:02
ERRO: 2015/06/30 10:47:48.9342 ->[192.168.48.12:39284|2e:ef:1a:56:84:80(host2)]: connection shutting down due to error: read tcp4 192.168.48.12:39284: connection reset by peer
INFO: 2015/06/30 10:47:48.934319 ->[192.168.48.12:39284|2e:ef:1a:56:84:80(host2)]: connection deleted

Logfile from c1 from successful run:

INFO: 2015/06/30 10:33:20.09492 Command line options: map[wait:20 iface:ethwe iprange:10.128.0.0/10 name:4e:14:17:0a:c6:44 nickname:host1 pktdebug:true port:6783]
INFO: 2015/06/30 10:33:20.095032 Command line peers: []
INFO: 2015/06/30 10:33:20.095184 Communication between peers is encrypted.
INFO: 2015/06/30 10:33:20.095512 Our name is 4e:14:17:0a:c6:44(host1)
INFO: 2015/06/30 10:33:20.095541 Assuming quorum size of 1
INFO: 2015/06/30 10:33:20.096874 [docker] Using Docker API on unix:///var/run/docker.sock: &[KernelVersion=3.16.0-37-generic Version=1.7.0 ApiVersion=1.19 GitCommit=0baf609 GoVersion=go1.4.2 Os=linux Arch=amd64]
INFO: 2015/06/30 10:33:20.099151 Sniffing traffic on &{1284 65535 ethwe ee:e6:0c:b6:42:b9 up|broadcast|multicast}
INFO: 2015/06/30 10:33:20.099419 Discovered our MAC ee:e6:0c:b6:42:b9
INFO: 2015/06/30 10:33:20.242878 Sniffed 90 bytes ( a929601304384903349e74bdba4d727cbea7d612c9f9f08b53d40167d56497c0 )
INFO: 2015/06/30 10:33:20.242916 Discovered local MAC 4e:14:17:0a:c6:44
INFO: 2015/06/30 10:33:20.242929 Forwarding 90 bytes ( a929601304384903349e74bdba4d727cbea7d612c9f9f08b53d40167d56497c0 ) 4e:14:17:0a:c6:44 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:20.567914 Sniffed 90 bytes ( 43ef2608f118a3b2f63ad6b45beb86aef89e626b43df3ec1a12b0bbfb1051706 )
INFO: 2015/06/30 10:33:20.568232 Discovered local MAC 96:ea:c5:19:00:12
INFO: 2015/06/30 10:33:20.568637 Forwarding 90 bytes ( 43ef2608f118a3b2f63ad6b45beb86aef89e626b43df3ec1a12b0bbfb1051706 ) 96:ea:c5:19:00:12 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:20.904592 Sniffed 90 bytes ( 0ead9ed4a543daa28d3466e5a21aae6d2ad1ecb2572c2f5aa064e499d9f0868c )
INFO: 2015/06/30 10:33:20.904705 Forwarding 90 bytes ( 0ead9ed4a543daa28d3466e5a21aae6d2ad1ecb2572c2f5aa064e499d9f0868c ) 4e:14:17:0a:c6:44 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:20.904769 Sniffed 70 bytes ( ae15a8ec37ed77764e43c545d14748d6105f7bd2b779b3526eec48a0cfdf1528 )
INFO: 2015/06/30 10:33:20.904802 Forwarding 70 bytes ( ae15a8ec37ed77764e43c545d14748d6105f7bd2b779b3526eec48a0cfdf1528 ) 4e:14:17:0a:c6:44 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:21.195109 Sniffed 90 bytes ( d81c51fd197875a2b7f7d7f83740529ae64b5868260c4e39532e6b0826bd542a )
INFO: 2015/06/30 10:33:21.195191 Forwarding 90 bytes ( d81c51fd197875a2b7f7d7f83740529ae64b5868260c4e39532e6b0826bd542a ) 96:ea:c5:19:00:12 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:21.195251 Sniffed 70 bytes ( 46e0162f292f3681812f7286e06edc519d69e5846198f2125cf622a824355b58 )
INFO: 2015/06/30 10:33:21.195286 Forwarding 70 bytes ( 46e0162f292f3681812f7286e06edc519d69e5846198f2125cf622a824355b58 ) 96:ea:c5:19:00:12 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:21.356765 ->[192.168.48.12:58934] connection accepted

INFO: 2015/06/30 10:33:21.357811 ->[192.168.48.12:58934|e2:1e:91:54:05:54(host2)]: completed handshake; using protocol version 1
INFO: 2015/06/30 10:33:21.357888 ->[192.168.48.12:58934|e2:1e:91:54:05:54(host2)]: connection added (new peer)
INFO: 2015/06/30 10:33:21.378778 ->[192.168.48.12:58934|e2:1e:91:54:05:54(host2)]: Effective PMTU set to 65449
INFO: 2015/06/30 10:33:21.39383 ->[192.168.48.12:58934|e2:1e:91:54:05:54(host2)]: connection fully established
INFO: 2015/06/30 10:33:21.394136 EMSGSIZE on send, expecting PMTU update (IP packet was 60088 bytes, payload was 60080 bytes)
INFO: 2015/06/30 10:33:21.394226 ->[192.168.48.12:58934|e2:1e:91:54:05:54(host2)]: Effective PMTU set to 1414
INFO: 2015/06/30 10:33:21.395213 ->[192.168.48.12:58934|e2:1e:91:54:05:54(host2)]: Effective PMTU verified at 1414
INFO: 2015/06/30 10:33:21.475173 Sniffed 90 bytes ( 0ead9ed4a543daa28d3466e5a21aae6d2ad1ecb2572c2f5aa064e499d9f0868c )
INFO: 2015/06/30 10:33:21.475276 Forwarding 90 bytes ( 0ead9ed4a543daa28d3466e5a21aae6d2ad1ecb2572c2f5aa064e499d9f0868c ) 4e:14:17:0a:c6:44 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:21.76754 Discovered remote MAC f2:1d:23:28:51:b7 at e2:1e:91:54:05:54(host2)
INFO: 2015/06/30 10:33:21.76754 Injecting 78 bytes ( 3e32c8128b10d3672aad73e7c3cb7209b32a651d92b4aceb45b1c64672b0ef33 ) f2:1d:23:28:51:b7 -> 33:33:ff:28:51:b7
INFO: 2015/06/30 10:33:21.76754 Relaying broadcast 78 bytes ( 3e32c8128b10d3672aad73e7c3cb7209b32a651d92b4aceb45b1c64672b0ef33 ) f2:1d:23:28:51:b7 -> 33:33:ff:28:51:b7
INFO: 2015/06/30 10:33:21.849711 Discovered remote MAC e2:1e:91:54:05:54 at e2:1e:91:54:05:54(host2)
INFO: 2015/06/30 10:33:21.849711 Injecting 78 bytes ( ca4018af3ebdbd35f005815c0e4cddd9ec440358c28f4d77bc8d60399e938a63 ) e2:1e:91:54:05:54 -> 33:33:ff:54:05:54
INFO: 2015/06/30 10:33:21.849767 Relaying broadcast 78 bytes ( ca4018af3ebdbd35f005815c0e4cddd9ec440358c28f4d77bc8d60399e938a63 ) e2:1e:91:54:05:54 -> 33:33:ff:54:05:54
INFO: 2015/06/30 10:33:22.198328 Sniffed 90 bytes ( d81c51fd197875a2b7f7d7f83740529ae64b5868260c4e39532e6b0826bd542a )
INFO: 2015/06/30 10:33:22.198329 Forwarding 90 bytes ( d81c51fd197875a2b7f7d7f83740529ae64b5868260c4e39532e6b0826bd542a ) 96:ea:c5:19:00:12 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:22.796734 Injecting 90 bytes ( 3330bd94d58d1448d6ad10976dd01ea6a518a703e5b97a1c979c7a1805ec19c8 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:22.796893 Relaying broadcast 90 bytes ( 3330bd94d58d1448d6ad10976dd01ea6a518a703e5b97a1c979c7a1805ec19c8 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:22.796954 Injecting 70 bytes ( b46e281813ba34cb26f3cc43c37a24fbad7541bc6871ec2abef739e37fde6c81 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:22.797017 Relaying broadcast 70 bytes ( b46e281813ba34cb26f3cc43c37a24fbad7541bc6871ec2abef739e37fde6c81 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:22.879543 Injecting 90 bytes ( 4b3b69cc21e919ee995aba8e84be18a8f011ae807ceae447f0d5215a7dc193d9 ) e2:1e:91:54:05:54 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:22.879633 Relaying broadcast 90 bytes ( 4b3b69cc21e919ee995aba8e84be18a8f011ae807ceae447f0d5215a7dc193d9 ) e2:1e:91:54:05:54 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:22.879708 Injecting 70 bytes ( 532c4e638a9e22b67229ce245000e1dde7c2dbaa8950dc3452ece5626d9c51db ) e2:1e:91:54:05:54 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:22.879753 Relaying broadcast 70 bytes ( 532c4e638a9e22b67229ce245000e1dde7c2dbaa8950dc3452ece5626d9c51db ) e2:1e:91:54:05:54 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:22.943805 Sniffed 42 bytes ( 323ff37b8312b155a85433a234cadb40bc5c6788f4ac61317d64ac17bb4443de )
INFO: 2015/06/30 10:33:22.946639 Discovered local MAC c2:25:b7:29:f6:8f
INFO: 2015/06/30 10:33:22.946694 Forwarding 42 bytes ( 323ff37b8312b155a85433a234cadb40bc5c6788f4ac61317d64ac17bb4443de ) c2:25:b7:29:f6:8f -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:33:22.946749 Sniffed 90 bytes ( 6dd27e82f6ef0ec4013c4abc863732b3e711447387cf05f982e6b3b3a3c1f3f5 )
INFO: 2015/06/30 10:33:22.947142 Forwarding 90 bytes ( 6dd27e82f6ef0ec4013c4abc863732b3e711447387cf05f982e6b3b3a3c1f3f5 ) c2:25:b7:29:f6:8f -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:23.137954 Injecting 90 bytes ( 4b3b69cc21e919ee995aba8e84be18a8f011ae807ceae447f0d5215a7dc193d9 ) e2:1e:91:54:05:54 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:23.138016 Relaying broadcast 90 bytes ( 4b3b69cc21e919ee995aba8e84be18a8f011ae807ceae447f0d5215a7dc193d9 ) e2:1e:91:54:05:54 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:23.146314 Sniffed 90 bytes ( 6dd27e82f6ef0ec4013c4abc863732b3e711447387cf05f982e6b3b3a3c1f3f5 )
INFO: 2015/06/30 10:33:23.146339 Forwarding 90 bytes ( 6dd27e82f6ef0ec4013c4abc863732b3e711447387cf05f982e6b3b3a3c1f3f5 ) c2:25:b7:29:f6:8f -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:23.303375 Sniffed 78 bytes ( 0857a132190a9516a2e5c93fa0eda08353fdf89ed0b3eba4867c639446e8a1a9 )
INFO: 2015/06/30 10:33:23.30347 Forwarding 78 bytes ( 0857a132190a9516a2e5c93fa0eda08353fdf89ed0b3eba4867c639446e8a1a9 ) c2:25:b7:29:f6:8f -> 33:33:ff:29:f6:8f
INFO: 2015/06/30 10:33:23.81172 Injecting 90 bytes ( 3330bd94d58d1448d6ad10976dd01ea6a518a703e5b97a1c979c7a1805ec19c8 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:23.811837 Relaying broadcast 90 bytes ( 3330bd94d58d1448d6ad10976dd01ea6a518a703e5b97a1c979c7a1805ec19c8 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.302655 Sniffed 90 bytes ( dc3cfe40c024e724bcfe4ab604a840aedce40d7df6048cc70ae100635d09baef )
INFO: 2015/06/30 10:33:24.302763 Forwarding 90 bytes ( dc3cfe40c024e724bcfe4ab604a840aedce40d7df6048cc70ae100635d09baef ) c2:25:b7:29:f6:8f -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.302844 Sniffed 70 bytes ( 3292fe4effbeb7a33090f2102af7e9ab6df464e8a7b511d095ac39122ae85796 )
INFO: 2015/06/30 10:33:24.302961 Forwarding 70 bytes ( 3292fe4effbeb7a33090f2102af7e9ab6df464e8a7b511d095ac39122ae85796 ) c2:25:b7:29:f6:8f -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:24.543025 Discovered remote MAC ae:dc:41:cd:7d:d9 at e2:1e:91:54:05:54(host2)
INFO: 2015/06/30 10:33:24.543116 Injecting 42 bytes ( 38dffbf1a69e267177184e3f3d59f9a261fe1fdbe93e166326879b61e09e0b87 ) ae:dc:41:cd:7d:d9 -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:33:24.543206 Relaying broadcast 42 bytes ( 38dffbf1a69e267177184e3f3d59f9a261fe1fdbe93e166326879b61e09e0b87 ) ae:dc:41:cd:7d:d9 -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:33:24.545857 Injecting 90 bytes ( 85b16f11f141213c94365bba5b6b7edafb51464a60e32463dd9ff145a14fa053 ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.545929 Relaying broadcast 90 bytes ( 85b16f11f141213c94365bba5b6b7edafb51464a60e32463dd9ff145a14fa053 ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.72868 Sniffed 42 bytes ( 3ea1cde3b7da5c1d523a2f409cc6a2230a191597ac74c49066b92218a66601f1 )
INFO: 2015/06/30 10:33:24.728716 Forwarding 42 bytes ( 3ea1cde3b7da5c1d523a2f409cc6a2230a191597ac74c49066b92218a66601f1 ) c2:25:b7:29:f6:8f -> ff:ff:ff:ff:ff:ff
INFO: 2015/06/30 10:33:24.730028 Injecting 42 bytes ( 2ed5a988b52f4a3404222b9bc4f476a2a28aceb458fe988125633b3c78f2b6a3 ) ae:dc:41:cd:7d:d9 -> c2:25:b7:29:f6:8f
INFO: 2015/06/30 10:33:24.7301 Sniffed 98 bytes ( 336fa287f9ddb45595e3017ed9f231d9998e9768fcdf3914a418c9fd7c708176 )
INFO: 2015/06/30 10:33:24.730153 Forwarding 98 bytes ( 336fa287f9ddb45595e3017ed9f231d9998e9768fcdf3914a418c9fd7c708176 ) c2:25:b7:29:f6:8f -> ae:dc:41:cd:7d:d9 (DF)
INFO: 2015/06/30 10:33:24.73055 Injecting 98 bytes ( 2413da91a044adbbe9b36cbd74c18ac4563ae8dcd461b13cc62a26dd4cc00a79 ) ae:dc:41:cd:7d:d9 -> c2:25:b7:29:f6:8f
INFO: 2015/06/30 10:33:24.78681 Sniffed 98 bytes ( 9f609c1bc09ff3c0964e02715188bbea15eba9c3e57853d4d796481b360eb228 )
INFO: 2015/06/30 10:33:24.787539 Forwarding 98 bytes ( 9f609c1bc09ff3c0964e02715188bbea15eba9c3e57853d4d796481b360eb228 ) c2:25:b7:29:f6:8f -> ae:dc:41:cd:7d:d9 (DF)
INFO: 2015/06/30 10:33:24.788177 Injecting 98 bytes ( 7a5aeade679056ab60ddefe7e8c68de5cac0a2d4a5af8e69093d3882e6505342 ) ae:dc:41:cd:7d:d9 -> c2:25:b7:29:f6:8f
INFO: 2015/06/30 10:33:24.862988 Injecting 90 bytes ( 85b16f11f141213c94365bba5b6b7edafb51464a60e32463dd9ff145a14fa053 ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.863053 Relaying broadcast 90 bytes ( 85b16f11f141213c94365bba5b6b7edafb51464a60e32463dd9ff145a14fa053 ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.886447 Sniffed 90 bytes ( dc3cfe40c024e724bcfe4ab604a840aedce40d7df6048cc70ae100635d09baef )
INFO: 2015/06/30 10:33:24.886473 Forwarding 90 bytes ( dc3cfe40c024e724bcfe4ab604a840aedce40d7df6048cc70ae100635d09baef ) c2:25:b7:29:f6:8f -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:24.906572 Sniffed 70 bytes ( ae15a8ec37ed77764e43c545d14748d6105f7bd2b779b3526eec48a0cfdf1528 )
INFO: 2015/06/30 10:33:24.906597 Forwarding 70 bytes ( ae15a8ec37ed77764e43c545d14748d6105f7bd2b779b3526eec48a0cfdf1528 ) 4e:14:17:0a:c6:44 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:25.202862 Sniffed 70 bytes ( 46e0162f292f3681812f7286e06edc519d69e5846198f2125cf622a824355b58 )
INFO: 2015/06/30 10:33:25.202954 Forwarding 70 bytes ( 46e0162f292f3681812f7286e06edc519d69e5846198f2125cf622a824355b58 ) 96:ea:c5:19:00:12 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:25.530091 Injecting 78 bytes ( dedda3a4e5a4eb9709016ddc94cf77ae995a45ef75ee3c8a9d98ded38444c1f2 ) ae:dc:41:cd:7d:d9 -> 33:33:ff:cd:7d:d9
INFO: 2015/06/30 10:33:25.530228 Relaying broadcast 78 bytes ( dedda3a4e5a4eb9709016ddc94cf77ae995a45ef75ee3c8a9d98ded38444c1f2 ) ae:dc:41:cd:7d:d9 -> 33:33:ff:cd:7d:d9
INFO: 2015/06/30 10:33:26.559324 Injecting 90 bytes ( d4e6bae5f7bca1f19507b27358983cd2e82895ddccae4543f738534dccafaf8a ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:26.559448 Relaying broadcast 90 bytes ( d4e6bae5f7bca1f19507b27358983cd2e82895ddccae4543f738534dccafaf8a ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16
INFO: 2015/06/30 10:33:26.559523 Injecting 70 bytes ( 54e5eb448bc9ef568e2709be091e5c97dc197a75dae02e866b019e18f3bea93c ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:26.559568 Relaying broadcast 70 bytes ( 54e5eb448bc9ef568e2709be091e5c97dc197a75dae02e866b019e18f3bea93c ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:26.78946 Injecting 42 bytes ( 418b0eb9a4799061a42213332a237bf7ae7346e9544b4f4db58c104174908aae ) ae:dc:41:cd:7d:d9 -> c2:25:b7:29:f6:8f
INFO: 2015/06/30 10:33:26.789587 Sniffed 42 bytes ( d10ad40c92b8ad97aece535831b911c4231211176718b29469e951b58e9b756d )
INFO: 2015/06/30 10:33:26.789652 Forwarding 42 bytes ( d10ad40c92b8ad97aece535831b911c4231211176718b29469e951b58e9b756d ) c2:25:b7:29:f6:8f -> ae:dc:41:cd:7d:d9
INFO: 2015/06/30 10:33:26.921639 Injecting 70 bytes ( b46e281813ba34cb26f3cc43c37a24fbad7541bc6871ec2abef739e37fde6c81 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:26.921751 Relaying broadcast 70 bytes ( b46e281813ba34cb26f3cc43c37a24fbad7541bc6871ec2abef739e37fde6c81 ) f2:1d:23:28:51:b7 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:27.007745 Injecting 70 bytes ( 532c4e638a9e22b67229ce245000e1dde7c2dbaa8950dc3452ece5626d9c51db ) e2:1e:91:54:05:54 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:27.007853 Relaying broadcast 70 bytes ( 532c4e638a9e22b67229ce245000e1dde7c2dbaa8950dc3452ece5626d9c51db ) e2:1e:91:54:05:54 -> 33:33:00:00:00:02
INFO: 2015/06/30 10:33:27.098294 Injecting 90 bytes ( d4e6bae5f7bca1f19507b27358983cd2e82895ddccae4543f738534dccafaf8a ) ae:dc:41:cd:7d:d9 -> 33:33:00:00:00:16

@bboreham bboreham self-assigned this Jun 30, 2015
@bboreham
Copy link
Contributor

I added some extra logging of heartbeats; we can see on this failed run that c2 never received any UDP heartbeats from c1:

c1:

INFO: 2015/06/30 11:24:26.570666 Command line options: map[name:d6:c4:ce:1e:66:da nickname:host1 port:6783 wait:20 debug:true iface:ethwe iprange:10.128.0.0/10]
INFO: 2015/06/30 11:24:26.570753 Command line peers: []
INFO: 2015/06/30 11:24:26.570902 Communication between peers is encrypted.
INFO: 2015/06/30 11:24:26.57109 Our name is d6:c4:ce:1e:66:da(host1)
INFO: 2015/06/30 11:24:26.57109 Assuming quorum size of 1
INFO: 2015/06/30 11:24:26.57464 [docker] Using Docker API on unix:///var/run/docker.sock: &[Version=1.7.0 ApiVersion=1.19 GitCommit=0baf609 GoVersion=go1.4.2 Os=linux Arch=amd64 KernelVersion=3.16.0-37-generic]
INFO: 2015/06/30 11:24:26.579456 Sniffing traffic on &{1524 65535 ethwe 06:db:c1:62:dd:75 up|broadcast|multicast}
INFO: 2015/06/30 11:24:26.579564 Discovered our MAC 06:db:c1:62:dd:75
INFO: 2015/06/30 11:24:26.759352 Discovered local MAC 1e:c0:a3:87:d8:15
INFO: 2015/06/30 11:24:27.146748 Discovered local MAC d6:c4:ce:1e:66:da
INFO: 2015/06/30 11:24:27.907232 ->[192.168.48.12:35591] connection accepted

INFO: 2015/06/30 11:24:27.908036 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: completed handshake; using protocol version 1
INFO: 2015/06/30 11:24:27.908104 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: connection added (new peer)
DEBU: 2015/06/30 11:24:27.91333 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Received UDP heartbeat
INFO: 2015/06/30 11:24:27.913672 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Effective PMTU set to 65449
DEBU: 2015/06/30 11:24:27.913719 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending initial UDP heartbeat
DEBU: 2015/06/30 11:24:27.913866 [allocator d6:c4:ce:1e:66:da]: Allocator.OnGossip: 512 bytes
DEBU: 2015/06/30 11:24:28.423036 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat
DEBU: 2015/06/30 11:24:28.916522 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat
DEBU: 2015/06/30 11:24:29.413839 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat
INFO: 2015/06/30 11:24:29.505687 Discovered local MAC 8a:de:af:aa:4a:86
DEBU: 2015/06/30 11:24:29.915427 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat
DEBU: 2015/06/30 11:24:30.415147 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat
DEBU: 2015/06/30 11:24:30.914134 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat
DEBU: 2015/06/30 11:24:31.414246 ->[192.168.48.12:35591|f6:f0:0d:04:25:61(host2)]: Sending UDP heartbeat

c2:

INFO: 2015/06/30 11:24:11.473918 Command line options: map[debug:true iface:ethwe iprange:10.128.0.0/10 name:f6:f0:0d:04:25:61 nickname:host2 port:6783 wait:20]
INFO: 2015/06/30 11:24:11.47402 Command line peers: [192.168.48.11]
INFO: 2015/06/30 11:24:11.474174 Communication between peers is encrypted.
INFO: 2015/06/30 11:24:11.474497 Our name is f6:f0:0d:04:25:61(host2)
INFO: 2015/06/30 11:24:11.474525 Assuming quorum size of 2
INFO: 2015/06/30 11:24:11.475423 [docker] Using Docker API on unix:///var/run/docker.sock: &[GoVersion=go1.4.2 Os=linux Arch=amd64 KernelVersion=3.16.0-37-generic Version=1.7.0 ApiVersion=1.19 GitCommit=0baf609]
INFO: 2015/06/30 11:24:11.477713 Sniffing traffic on &{1016 65535 ethwe d2:68:60:a5:fe:98 up|broadcast|multicast}
INFO: 2015/06/30 11:24:11.477865 Discovered our MAC d2:68:60:a5:fe:98
INFO: 2015/06/30 11:24:11.47933 ->[192.168.48.11:6783] attempting connection

INFO: 2015/06/30 11:24:11.480668 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: completed handshake; using protocol version 1
INFO: 2015/06/30 11:24:11.480795 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: Effective PMTU set to 65449
INFO: 2015/06/30 11:24:11.480887 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: connection added (new peer)
DEBU: 2015/06/30 11:24:11.485234 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: Sending initial UDP heartbeat
DEBU: 2015/06/30 11:24:11.485891 [allocator f6:f0:0d:04:25:61]: Allocator.OnGossip: 512 bytes
INFO: 2015/06/30 11:24:11.486278 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: connection fully established
INFO: 2015/06/30 11:24:11.506935 EMSGSIZE on send, expecting PMTU update (IP packet was 60088 bytes, payload was 60080 bytes)
INFO: 2015/06/30 11:24:11.507055 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: Effective PMTU set to 1414
INFO: 2015/06/30 11:24:11.526082 ->[192.168.48.11:6783|d6:c4:ce:1e:66:da(host1)]: Effective PMTU verified at 1414
INFO: 2015/06/30 11:24:12.091223 Discovered local MAC f2:5a:a5:8f:3f:57
INFO: 2015/06/30 11:24:12.271224 Discovered local MAC f6:f0:0d:04:25:61
INFO: 2015/06/30 11:24:14.644665 Discovered local MAC fa:e3:df:30:8d:7e

(note that the clocks on these two VMs were about 16 seconds out)

@bboreham
Copy link
Contributor

Further investigation: I disabled encryption, but the intermittent failures continue.

Packet-capture indicates that the UDP heartbeats are being sent to a high-numbered port, e.g. 54545, and then rejected.

conntrack -L, filtered, shows:

udp      17 29 src=172.17.1.133 dst=192.168.48.12 sport=6783 dport=59736 [UNREPLIED] src=192.168.48.12 dst=192.168.48.11 sport=59736 dport=6783 mark=0 use=1
udp      17 28 src=172.17.42.1 dst=172.17.1.133 sport=59736 dport=6783 [UNREPLIED] src=172.17.1.133 dst=172.17.42.1 sport=6783 dport=59736 mark=0 use=1
tcp      6 431984 ESTABLISHED src=192.168.48.12 dst=192.168.48.11 sport=34388 dport=6783 src=172.17.1.133 dst=192.168.48.12 sport=6783 dport=34388 [ASSURED] mark=0 use=1
udp      17 28 src=192.168.48.12 dst=192.168.48.11 sport=6783 dport=6783 [UNREPLIED] src=192.168.48.11 dst=192.168.48.12 sport=6783 dport=6783 mark=0 use=1

for a working run, all UDP packets have source and destination ports of 6783, and conntrack -L shows:

tcp      6 431999 ESTABLISHED src=192.168.48.12 dst=192.168.48.11 sport=55549 dport=6783 src=172.17.1.135 dst=192.168.48.12 sport=6783 dport=55549 [ASSURED] mark=0 use=1
udp      17 170 src=192.168.48.12 dst=192.168.48.11 sport=6783 dport=6783 src=172.17.1.135 dst=192.168.48.12 sport=6783 dport=6783 [ASSURED] mark=0 use=1

@rade
Copy link
Member

rade commented Jun 30, 2015 via email

@bboreham
Copy link
Contributor

I tried adding this line before rm_containers in start_suite in config.sh:

run_on $host sudo conntrack -D -p udp --dport 6783

but it still failed intermittently.

@bboreham
Copy link
Contributor

Well, it failed on the 8th attempt, and then didn't fail again for the next 22 attempts, which represents an improvement. Perhaps that 1-in-30 failure was for a different reason.

@bboreham
Copy link
Contributor

Interestingly, we were already calling weave reset, which calls conntrack -D. But, reversing the order of the weave reset and rm_containers lines makes it work far more reliably.

This was referenced Jun 30, 2015
Closed
Merged
@rade rade added this to the 1.0.2 milestone Jul 1, 2015
@rade rade closed this as completed in a05a3c4 Jul 1, 2015
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@bboreham bboreham

Labels
bug
Projects
None yet
Milestone
1.0.2
Development

No branches or pull requests
3 participants
@rade @awh @bboreham