{"action":"created","issue":{"url":"https://api.github.com/repos/coreos/etcd/issues/5679","repository_url":"https://api.github.com/repos/coreos/etcd","labels_url":"https://api.github.com/repos/coreos/etcd/issues/5679/labels{/name}","comments_url":"https://api.github.com/repos/coreos/etcd/issues/5679/comments","events_url":"https://api.github.com/repos/coreos/etcd/issues/5679/events","html_url":"https://github.com/coreos/etcd/issues/5679","id":160527790,"number":5679,"title":"functional-tester: possible live-lock after recovery","user":{"login":"gyuho","id":6799218,"avatar_url":"https://avatars.githubusercontent.com/u/6799218?v=3","gravatar_id":"","url":"https://api.github.com/users/gyuho","html_url":"https://github.com/gyuho","followers_url":"https://api.github.com/users/gyuho/followers","following_url":"https://api.github.com/users/gyuho/following{/other_user}","gists_url":"https://api.github.com/users/gyuho/gists{/gist_id}","starred_url":"https://api.github.com/users/gyuho/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gyuho/subscriptions","organizations_url":"https://api.github.com/users/gyuho/orgs","repos_url":"https://api.github.com/users/gyuho/repos","events_url":"https://api.github.com/users/gyuho/events{/privacy}","received_events_url":"https://api.github.com/users/gyuho/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/coreos/etcd/labels/component/functional-tester","name":"component/functional-tester","color":"0052cc"}],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2016-06-15T21:25:58Z","updated_at":"2016-06-17T20:49:09Z","closed_at":"2016-06-17T20:49:08Z","body":"Still investigating...\r\n\r\n- Pretty easy to reproduce with 8-CPU machines (but very infrequent in 4-CPU machines, only happens 1 in every +2000 rounds)\r\n- Rebuilding kv index takes only 2~3 seconds, so snapshot cycle is not the problem here\r\n\r\n```bash\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #1 (normal)\r\n\r\n2016-06-14 14:27:41.210646 I | raft: 8761235f5076cdf became follower at term 7\r\n2016-06-14 14:27:41.210681 I | raft: newRaft 8761235f5076cdf [peers: [8761235f5076cdf,8e1638a536730aeb,cdde8566ef67fec3], term: 7, commit: 99012, applied: 90273, lastindex: 99063, lastterm: 7]\r\n2016-06-14 14:27:41.214392 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:27:41.214424 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:27:41.214447 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:27:41.214457 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:27:41.254892 I | mvcc: [DEBUG] rebuilding 98971 keys\r\n2016-06-14 14:27:41.556114 I | mvcc: [DEBUG] rebuilt 98971 keys (took 301.262478ms)\r\n2016-06-14 14:27:41.556176 I | mvcc: [DEBUG] restore done for 98971 keys\r\n\r\n----------------------------> restore after recovery took <1s\r\n\r\n----------------------------> then got snapshot, restore triggers again\r\n\r\n2016-06-14 14:27:41.690338 I | snap: saved database snapshot to disk [total bytes: 22380544]\r\n2016-06-14 14:27:41.690391 I | rafthttp: received and saved database snapshot [index: 124384, from: 8e1638a536730aeb] successfully\r\n2016-06-14 14:27:41.690606 I | raft: 8761235f5076cdf [commit: 99063, lastindex: 99063, lastterm: 7] starts to restore snapshot [index: 124384, term: 7]\r\n2016-06-14 14:27:41.690659 I | raft: log [committed=99063, applied=99063, unstable.offset=99064, len(unstable.Entries)=0] starts to restore snapshot [index: 124384, term: 7]\r\n2016-06-14 14:27:41.690696 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 124385, match = 124384, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:27:41.690707 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 124385, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:27:41.690719 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 124385, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:27:41.690744 I | raft: 8761235f5076cdf [commit: 124384] restored snapshot [index: 124384, term: 7]\r\n2016-06-14 14:27:41.690918 I | etcdserver: applying snapshot at index 90273...\r\n\r\n----------------------------> restore triggers...\r\n\r\n2016-06-14 14:27:41.693113 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:27:41.694865 I | etcdserver: raft applied incoming snapshot at index 124384\r\n2016-06-14 14:27:41.751947 I | mvcc: [DEBUG] rebuilding 124340 keys\r\n2016-06-14 14:27:42.103934 I | mvcc: [DEBUG] rebuilt 124340 keys (took 353.633779ms)\r\n2016-06-14 14:27:42.103973 I | mvcc: [DEBUG] restore done for 124340 keys\r\n\r\n----------------------------> compacting 496156 entries took 6s\r\n\r\n2016-06-14 14:28:23.029633 I | mvcc: finished scheduled compaction at 496157 (took 5.800686104s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #2 (normal)\r\n\r\n2016-06-14 14:28:51.169545 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:28:51.173119 I | mvcc: restore compact to 496157\r\n2016-06-14 14:28:51.298118 I | mvcc: [DEBUG] rebuilding 448948 keys\r\n2016-06-14 14:28:52.700746 I | mvcc: [DEBUG] rebuilt 448948 keys (took 1.402632395s)\r\n2016-06-14 14:28:52.700824 I | mvcc: [DEBUG] restore done for 448948 keys\r\n\r\n2016-06-14 14:28:53.314422 I | snap: saved database snapshot to disk [total bytes: 113549312]\r\n2016-06-14 14:28:53.314477 I | rafthttp: received and saved database snapshot [index: 763816, from: cdde8566ef67fec3] successfully\r\n\r\n2016-06-14 14:28:53.317575 I | etcdserver: raft applied incoming snapshot at index 763816\r\n2016-06-14 14:28:53.321374 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:28:53.321482 I | mvcc: restore compact to 496157\r\n2016-06-14 14:28:53.523597 I | mvcc: [DEBUG] rebuilding 483187 keys\r\n2016-06-14 14:28:55.370325 I | mvcc: [DEBUG] rebuilt 483187 keys (took 1.849483737s)\r\n2016-06-14 14:28:55.370371 I | mvcc: [DEBUG] restore done for 483187 keys\r\n2016-06-14 14:28:55.370388 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:28:55.370414 I | etcdserver: recovering lessor...\r\n2016-06-14 14:28:55.370562 I | etcdserver: closing old backend...\r\n2016-06-14 14:28:55.372264 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:28:55.372752 I | etcdserver: recovering alarms...\r\n2016-06-14 14:28:55.373980 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:28:55.373995 I | etcdserver: recovering auth store...\r\n2016-06-14 14:28:55.374007 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:28:55.374015 I | etcdserver: recovering store v2...\r\n2016-06-14 14:28:55.375163 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:28:55.375655 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:28:55.375772 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:28:55.375810 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:28:55.375824 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:28:55.375837 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:28:55.375845 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:28:55.375853 I | etcdserver: removing old peers from network...\r\n\r\n2016-06-14 14:29:35.256261 I | mvcc: [DEBUG] compacting 814719 entries\r\n2016-06-14 14:29:35.261631 I | mvcc: finished scheduled compaction at 1095158 (took 9.964671221s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #3 (normal)\r\n\r\n2016-06-14 14:29:50.811764 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:29:50.815995 I | mvcc: restore compact to 1095158\r\n2016-06-14 14:29:50.983686 I | mvcc: [DEBUG] rebuilding 549325 keys\r\n2016-06-14 14:29:52.500570 I | mvcc: [DEBUG] rebuilt 549325 keys (took 1.516887985s)\r\n2016-06-14 14:29:52.500641 I | mvcc: [DEBUG] restore done for 549325 keys\r\n\r\n2016-06-14 14:29:53.513309 I | snap: saved database snapshot to disk [total bytes: 175276032]\r\n2016-06-14 14:29:53.513349 I | rafthttp: received and saved database snapshot [index: 1404869, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:29:53.513484 I | raft: 8761235f5076cdf [commit: 1399210, lastindex: 1399210, lastterm: 19] starts to restore snapshot [index: 1404869, term: 19]\r\n2016-06-14 14:29:53.513521 I | raft: log [committed=1399210, applied=1399210, unstable.offset=1399211, len(unstable.Entries)=0] starts to restore snapshot [index: 1404869, term: 19]\r\n2016-06-14 14:29:53.513557 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 1404870, match = 1404869, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:29:53.513572 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 1404870, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:29:53.513584 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 1404870, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:29:53.513591 I | raft: 8761235f5076cdf [commit: 1404869] restored snapshot [index: 1404869, term: 19]\r\n2016-06-14 14:29:53.513782 I | etcdserver: applying snapshot at index 1397920...\r\n2016-06-14 14:29:53.516508 I | etcdserver: raft applied incoming snapshot at index 1404869\r\n2016-06-14 14:29:53.525573 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:29:53.525639 I | mvcc: restore compact to 1095158\r\n2016-06-14 14:29:53.747023 I | mvcc: [DEBUG] rebuilding 556269 keys\r\n2016-06-14 14:29:55.828105 I | mvcc: [DEBUG] rebuilt 556269 keys (took 2.081081523s)\r\n2016-06-14 14:29:55.828147 I | mvcc: [DEBUG] restore done for 556269 keys\r\n2016-06-14 14:29:55.828159 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:29:55.828176 I | etcdserver: recovering lessor...\r\n2016-06-14 14:29:55.828298 I | etcdserver: closing old backend...\r\n2016-06-14 14:29:55.830433 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:29:55.830457 I | etcdserver: recovering alarms...\r\n2016-06-14 14:29:55.832448 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:29:55.832842 I | etcdserver: recovering auth store...\r\n2016-06-14 14:29:55.832861 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:29:55.832867 I | etcdserver: recovering store v2...\r\n2016-06-14 14:29:55.835190 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:29:55.835212 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:29:55.835311 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:29:55.835325 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:29:55.835334 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:29:55.835346 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:29:55.835353 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:29:55.835358 I | etcdserver: removing old peers from network...\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #4 (normal)\r\n\r\n2016-06-14 14:31:23.013621 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:31:23.021329 I | mvcc: restore compact to 2038386\r\n2016-06-14 14:31:23.266096 I | mvcc: [DEBUG] rebuilding 553996 keys\r\n2016-06-14 14:31:25.399706 I | mvcc: [DEBUG] rebuilt 553996 keys (took 2.133575347s)\r\n2016-06-14 14:31:25.399797 I | mvcc: [DEBUG] restore done for 553996 keys\r\n\r\n2016-06-14 14:31:25.417849 I | rafthttp: receiving database snapshot [index:2389707, from cdde8566ef67fec3] ...\r\n2016-06-14 14:31:26.749618 I | snap: saved database snapshot to disk [total bytes: 248233984]\r\n2016-06-14 14:31:26.749668 I | rafthttp: received and saved database snapshot [index: 2389707, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:31:26.749844 I | raft: 8761235f5076cdf [commit: 2342951, lastindex: 2343131, lastterm: 25] starts to restore snapshot [index: 2389707, term: 26]\r\n2016-06-14 14:31:26.749869 I | raft: log [committed=2342951, applied=2342951, unstable.offset=2343132, len(unstable.Entries)=0] starts to restore snapshot [index: 2389707, term: 26]\r\n2016-06-14 14:31:26.749901 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 2389708, match = 2389707, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:31:26.749916 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 2389708, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:31:26.749929 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 2389708, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:31:26.749936 I | raft: 8761235f5076cdf [commit: 2389707] restored snapshot [index: 2389707, term: 26]\r\n2016-06-14 14:31:26.750127 I | etcdserver: applying snapshot at index 2335550...\r\n2016-06-14 14:31:26.753120 I | etcdserver: raft applied incoming snapshot at index 2389707\r\n2016-06-14 14:31:26.773654 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:31:26.773738 I | mvcc: restore compact to 2038386\r\n2016-06-14 14:31:27.089292 I | mvcc: [DEBUG] rebuilding 600743 keys\r\n2016-06-14 14:31:29.298641 I | mvcc: [DEBUG] rebuilt 600743 keys (took 2.209353721s)\r\n2016-06-14 14:31:29.298695 I | mvcc: [DEBUG] restore done for 600743 keys\r\n2016-06-14 14:31:29.298708 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:31:29.298721 I | etcdserver: recovering lessor...\r\n2016-06-14 14:31:29.298895 I | etcdserver: closing old backend...\r\n2016-06-14 14:31:29.307279 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:31:29.307314 I | etcdserver: recovering alarms...\r\n2016-06-14 14:31:29.311042 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:31:29.311069 I | etcdserver: recovering auth store...\r\n2016-06-14 14:31:29.311698 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:31:29.311709 I | etcdserver: recovering store v2...\r\n2016-06-14 14:31:29.312550 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:31:29.312568 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:31:29.312659 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:31:29.312670 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:31:29.312677 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:31:29.312685 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:31:29.312690 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:31:29.312695 I | etcdserver: removing old peers from network...\r\n\r\n2016-06-14 14:32:26.528052 I | mvcc: [DEBUG] compacting 1126578 entries\r\n2016-06-14 14:32:26.533873 I | mvcc: finished scheduled compaction at 2915040 (took 13.812670076s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #5 (normal)\r\n\r\n2016-06-14 14:32:40.259894 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:32:40.267699 I | mvcc: restore compact to 2915040\r\n2016-06-14 14:32:40.571175 I | mvcc: [DEBUG] rebuilding 531048 keys\r\n2016-06-14 14:32:42.227593 I | mvcc: [DEBUG] rebuilt 531048 keys (took 1.656411182s)\r\n2016-06-14 14:32:42.227690 I | mvcc: [DEBUG] restore done for 531048 keys\r\n2016-06-14 14:32:42.234907 I | rafthttp: starting peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:32:42.278142 I | rafthttp: receiving database snapshot [index:3208014, from cdde8566ef67fec3] ...\r\n2016-06-14 14:32:43.604086 I | snap: saved database snapshot to disk [total bytes: 248274944]\r\n2016-06-14 14:32:43.604132 I | rafthttp: received and saved database snapshot [index: 3208014, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:32:43.604320 I | raft: 8761235f5076cdf [commit: 3198605, lastindex: 3198605, lastterm: 32] starts to restore snapshot [index: 3208014, term: 32]\r\n2016-06-14 14:32:43.604377 I | raft: log [committed=3198605, applied=3198605, unstable.offset=3198606, len(unstable.Entries)=0] starts to restore snapshot [index: 3208014, term: 32]\r\n2016-06-14 14:32:43.604400 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 3208015, match = 3208014, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:32:43.604418 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 3208015, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:32:43.604434 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 3208015, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:32:43.604443 I | raft: 8761235f5076cdf [commit: 3208014] restored snapshot [index: 3208014, term: 32]\r\n2016-06-14 14:32:43.604610 I | etcdserver: applying snapshot at index 3191679...\r\n2016-06-14 14:32:43.607307 I | etcdserver: raft applied incoming snapshot at index 3208014\r\n2016-06-14 14:32:43.638026 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:32:43.638109 I | mvcc: restore compact to 2915040\r\n2016-06-14 14:32:43.858570 I | mvcc: [DEBUG] rebuilding 542319 keys\r\n2016-06-14 14:32:46.016989 I | mvcc: [DEBUG] rebuilt 542319 keys (took 2.158411781s)\r\n2016-06-14 14:32:46.017053 I | mvcc: [DEBUG] restore done for 542319 keys\r\n2016-06-14 14:32:46.017068 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:32:46.017078 I | etcdserver: recovering lessor...\r\n2016-06-14 14:32:46.017205 I | etcdserver: closing old backend...\r\n2016-06-14 14:32:46.021248 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:32:46.021273 I | etcdserver: recovering alarms...\r\n2016-06-14 14:32:46.024444 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:32:46.024467 I | etcdserver: recovering auth store...\r\n2016-06-14 14:32:46.024480 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:32:46.024486 I | etcdserver: recovering store v2...\r\n2016-06-14 14:32:46.025620 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:32:46.025638 I | etcdserver: recovering cluster configuration...\r\n\r\n2016-06-14 14:33:57.678002 I | mvcc: [DEBUG] compacting 1177896 entries\r\n2016-06-14 14:33:57.689736 I | mvcc: finished scheduled compaction at 3842936 (took 14.316265066s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #6 (normal)\r\n\r\n2016-06-14 14:34:34.799729 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:34:34.813325 I | mvcc: restore compact to 3842936\r\n2016-06-14 14:34:35.065938 I | mvcc: [DEBUG] rebuilding 815019 keys\r\n2016-06-14 14:34:37.480788 I | mvcc: [DEBUG] rebuilt 815019 keys (took 2.414860137s)\r\n2016-06-14 14:34:37.480861 I | mvcc: [DEBUG] restore done for 815019 keys\r\n\r\n2016-06-14 14:34:37.550705 I | etcdserver: compacted raft log at 4403830\r\n2016-06-14 14:34:38.807899 I | snap: saved database snapshot to disk [total bytes: 248274944]\r\n2016-06-14 14:34:38.807948 I | rafthttp: received and saved database snapshot [index: 4452526, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:34:38.808108 I | raft: 8761235f5076cdf [commit: 4408830, lastindex: 4408931, lastterm: 39] starts to restore snapshot [index: 4452526, term: 40]\r\n2016-06-14 14:34:38.808137 I | raft: log [committed=4408830, applied=4408830, unstable.offset=4408932, len(unstable.Entries)=0] starts to restore snapshot [index: 4452526, term: 40]\r\n2016-06-14 14:34:38.808166 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 4452527, match = 4452526, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:34:38.808181 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 4452527, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:34:38.808197 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 4452527, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:34:38.808205 I | raft: 8761235f5076cdf [commit: 4452526] restored snapshot [index: 4452526, term: 40]\r\n2016-06-14 14:34:38.808336 I | etcdserver: applying snapshot at index 4408830...\r\n2016-06-14 14:34:38.811273 I | etcdserver: raft applied incoming snapshot at index 4452526\r\n2016-06-14 14:34:38.830857 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:34:38.831084 I | mvcc: restore compact to 3842936\r\n2016-06-14 14:34:39.136092 I | mvcc: [DEBUG] rebuilding 858703 keys\r\n2016-06-14 14:34:42.254415 I | mvcc: [DEBUG] rebuilt 858703 keys (took 3.118317617s)\r\n2016-06-14 14:34:42.254460 I | mvcc: [DEBUG] restore done for 858703 keys\r\n2016-06-14 14:34:42.254478 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:34:42.254494 I | etcdserver: recovering lessor...\r\n2016-06-14 14:34:42.254656 I | etcdserver: closing old backend...\r\n2016-06-14 14:34:42.261564 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:34:42.261602 I | etcdserver: recovering alarms...\r\n2016-06-14 14:34:42.264342 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:34:42.264363 I | etcdserver: recovering auth store...\r\n2016-06-14 14:34:42.264405 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:34:42.264432 I | etcdserver: recovering store v2...\r\n2016-06-14 14:34:42.265618 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:34:42.265652 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:34:42.265737 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:34:42.266299 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:34:42.266311 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:34:42.266320 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:34:42.266333 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:34:42.266372 I | etcdserver: removing old peers from network...\r\n\r\n2016-06-14 14:35:29.811635 I | mvcc: [DEBUG] compacting 1281052 entries\r\n2016-06-14 14:35:29.818744 I | mvcc: finished scheduled compaction at 4873987 (took 15.824063436s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #7 (normal)\r\n\r\n2016-06-14 14:35:41.082682 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:35:41.089981 I | mvcc: restore compact to 4873987\r\n2016-06-14 14:35:41.316995 I | mvcc: [DEBUG] rebuilding 564775 keys\r\n2016-06-14 14:35:42.941976 I | mvcc: [DEBUG] rebuilt 564775 keys (took 1.625001668s)\r\n2016-06-14 14:35:42.942047 I | mvcc: [DEBUG] restore done for 564775 keys\r\n\r\n2016-06-14 14:35:42.989501 I | rafthttp: receiving database snapshot [index:5229095, from cdde8566ef67fec3] ...\r\n2016-06-14 14:35:44.570551 I | snap: saved database snapshot to disk [total bytes: 265162752]\r\n2016-06-14 14:35:44.570610 I | rafthttp: received and saved database snapshot [index: 5229095, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:35:44.570804 I | raft: 8761235f5076cdf [commit: 5192685, lastindex: 5192685, lastterm: 44] starts to restore snapshot [index: 5229095, term: 44]\r\n2016-06-14 14:35:44.570838 I | raft: log [committed=5192685, applied=5192685, unstable.offset=5192686, len(unstable.Entries)=0] starts to restore snapshot [index: 5229095, term: 44]\r\n2016-06-14 14:35:44.570875 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 5229096, match = 5229095, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:35:44.570898 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 5229096, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:35:44.570909 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 5229096, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:35:44.570920 I | raft: 8761235f5076cdf [commit: 5229095] restored snapshot [index: 5229095, term: 44]\r\n2016-06-14 14:35:44.571179 I | etcdserver: applying snapshot at index 5183175...\r\n2016-06-14 14:35:44.574696 I | etcdserver: raft applied incoming snapshot at index 5229095\r\n2016-06-14 14:35:44.612260 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:35:44.612332 I | mvcc: restore compact to 4873987\r\n2016-06-14 14:35:44.957358 I | mvcc: [DEBUG] rebuilding 604091 keys\r\n2016-06-14 14:35:47.712751 I | mvcc: [DEBUG] rebuilt 604091 keys (took 2.755412106s)\r\n2016-06-14 14:35:47.712801 I | mvcc: [DEBUG] restore done for 604091 keys\r\n2016-06-14 14:35:47.712814 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:35:47.712839 I | etcdserver: recovering lessor...\r\n2016-06-14 14:35:47.712956 I | etcdserver: closing old backend...\r\n2016-06-14 14:35:47.717197 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:35:47.717228 I | etcdserver: recovering alarms...\r\n2016-06-14 14:35:47.723026 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:35:47.723050 I | etcdserver: recovering auth store...\r\n2016-06-14 14:35:47.723065 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:35:47.723071 I | etcdserver: recovering store v2...\r\n2016-06-14 14:35:47.724250 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:35:47.724267 I | etcdserver: recovering cluster configuration...\r\n\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #8 (normal)\r\n\r\n2016-06-14 14:39:14.354885 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:39:14.362627 I | mvcc: restore compact to 7200113\r\n2016-06-14 14:39:14.585454 I | mvcc: [DEBUG] rebuilding 691429 keys\r\n2016-06-14 14:39:16.572789 I | mvcc: [DEBUG] rebuilt 691429 keys (took 1.98736427s)\r\n2016-06-14 14:39:16.572857 I | mvcc: [DEBUG] restore done for 691429 keys\r\n\r\n2016-06-14 14:39:18.336888 I | snap: saved database snapshot to disk [total bytes: 319389696]\r\n2016-06-14 14:39:18.336937 I | rafthttp: received and saved database snapshot [index: 7655200, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:39:18.337082 I | raft: 8761235f5076cdf [commit: 7644740, lastindex: 7644740, lastterm: 63] starts to restore snapshot [index: 7655200, term: 63]\r\n2016-06-14 14:39:18.337112 I | raft: log [committed=7644740, applied=7644740, unstable.offset=7644741, len(unstable.Entries)=0] starts to restore snapshot [index: 7655200, term: 63]\r\n2016-06-14 14:39:18.337135 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 7655201, match = 7655200, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:39:18.337145 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 7655201, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:39:18.337156 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 7655201, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:39:18.337174 I | raft: 8761235f5076cdf [commit: 7655200] restored snapshot [index: 7655200, term: 63]\r\n2016-06-14 14:39:18.337323 I | etcdserver: applying snapshot at index 7642977...\r\n2016-06-14 14:39:18.340143 I | etcdserver: raft applied incoming snapshot at index 7655200\r\n2016-06-14 14:39:18.368115 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:39:18.368184 I | mvcc: restore compact to 7200113\r\n2016-06-14 14:39:18.601525 I | mvcc: [DEBUG] rebuilding 703647 keys\r\n2016-06-14 14:39:20.873749 I | mvcc: [DEBUG] rebuilt 703647 keys (took 2.275646916s)\r\n2016-06-14 14:39:20.873792 I | mvcc: [DEBUG] restore done for 703647 keys\r\n2016-06-14 14:39:20.873803 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:39:20.873816 I | etcdserver: recovering lessor...\r\n2016-06-14 14:39:20.873958 I | etcdserver: closing old backend...\r\n2016-06-14 14:39:20.882977 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:39:20.883010 I | etcdserver: recovering alarms...\r\n2016-06-14 14:39:20.886728 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:39:20.886760 I | etcdserver: recovering auth store...\r\n2016-06-14 14:39:20.886779 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:39:20.886787 I | etcdserver: recovering store v2...\r\n2016-06-14 14:39:20.888349 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:39:20.888368 I | etcdserver: recovering cluster configuration...\r\n\r\n2016-06-14 14:40:40.792351 I | mvcc: [DEBUG] compacting 1509127 entries\r\n2016-06-14 14:40:40.801970 I | mvcc: finished scheduled compaction at 8459239 (took 18.723051864s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #9 (normal)\r\n\r\n2016-06-14 14:40:52.013895 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:40:52.021542 I | mvcc: restore compact to 8459239\r\n2016-06-14 14:40:52.329395 I | mvcc: [DEBUG] rebuilding 646799 keys\r\n2016-06-14 14:40:54.405768 I | mvcc: [DEBUG] rebuilt 646799 keys (took 2.076364165s)\r\n2016-06-14 14:40:54.405853 I | mvcc: [DEBUG] restore done for 646799 keys\r\n\r\n2016-06-14 14:40:56.208403 I | etcdserver: applying snapshot at index 8852017...\r\n2016-06-14 14:40:56.211540 I | etcdserver: raft applied incoming snapshot at index 8901005\r\n2016-06-14 14:40:56.241489 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:40:56.241579 I | mvcc: restore compact to 8459239\r\n2016-06-14 14:40:56.576299 I | mvcc: [DEBUG] rebuilding 690129 keys\r\n2016-06-14 14:40:59.102057 I | mvcc: [DEBUG] rebuilt 690129 keys (took 2.52576344s)\r\n2016-06-14 14:40:59.102107 I | mvcc: [DEBUG] restore done for 690129 keys\r\n2016-06-14 14:40:59.102132 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:40:59.102148 I | etcdserver: recovering lessor...\r\n2016-06-14 14:40:59.102238 I | etcdserver: closing old backend...\r\n2016-06-14 14:40:59.106526 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:40:59.106552 I | etcdserver: recovering alarms...\r\n2016-06-14 14:40:59.112398 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:40:59.112426 I | etcdserver: recovering auth store...\r\n2016-06-14 14:40:59.112444 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:40:59.112454 I | etcdserver: recovering store v2...\r\n2016-06-14 14:40:59.113917 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:40:59.113939 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:40:59.114036 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:40:59.114048 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:40:59.114056 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:40:59.114065 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:40:59.114070 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:40:59.114075 I | etcdserver: removing old peers from network...\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #10 (normal)\r\n\r\n2016-06-14 14:41:18.928849 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:41:18.935551 I | mvcc: restore compact to 8459239\r\n2016-06-14 14:41:19.258975 I | mvcc: [DEBUG] rebuilding 971035 keys\r\n2016-06-14 14:41:22.080563 I | mvcc: [DEBUG] rebuilt 971035 keys (took 2.82160113s)\r\n2016-06-14 14:41:22.080646 I | mvcc: [DEBUG] restore done for 971035 keys\r\n2016-06-14 14:41:22.087208 I | rafthttp: starting peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:41:22.133778 I | rafthttp: receiving database snapshot [index:9240663, from cdde8566ef67fec3] ...\r\n2016-06-14 14:41:22.190782 I | etcdserver: start to snapshot (applied: 9181954, lastsnap: 9052864)\r\n2016-06-14 14:41:22.195834 I | etcdserver: saved snapshot at index 9181954\r\n2016-06-14 14:41:22.196013 I | etcdserver: compacted raft log at 9176954\r\n2016-06-14 14:41:23.879105 I | snap: saved database snapshot to disk [total bytes: 319389696]\r\n2016-06-14 14:41:23.879149 I | rafthttp: received and saved database snapshot [index: 9240663, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:41:23.879295 I | raft: 8761235f5076cdf [commit: 9181954, lastindex: 9182080, lastterm: 67] starts to restore snapshot [index: 9240663, term: 68]\r\n2016-06-14 14:41:23.879326 I | raft: log [committed=9181954, applied=9181954, unstable.offset=9182081, len(unstable.Entries)=0] starts to restore snapshot [index: 9240663, term: 68]\r\n2016-06-14 14:41:23.879351 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 9240664, match = 9240663, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:41:23.879361 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 9240664, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:41:23.879371 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 9240664, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:41:23.879378 I | raft: 8761235f5076cdf [commit: 9240663] restored snapshot [index: 9240663, term: 68]\r\n2016-06-14 14:41:23.879499 I | etcdserver: applying snapshot at index 9181954...\r\n2016-06-14 14:41:23.882844 I | etcdserver: raft applied incoming snapshot at index 9240663\r\n2016-06-14 14:41:23.902607 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:41:23.902676 I | mvcc: restore compact to 8459239\r\n2016-06-14 14:41:24.266753 I | mvcc: [DEBUG] rebuilding 1029731 keys\r\n2016-06-14 14:41:27.912047 I | mvcc: [DEBUG] rebuilt 1029731 keys (took 3.645289928s)\r\n2016-06-14 14:41:27.912081 I | mvcc: [DEBUG] restore done for 1029731 keys\r\n2016-06-14 14:41:27.912091 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:41:27.912099 I | etcdserver: recovering lessor...\r\n2016-06-14 14:41:27.912226 I | etcdserver: closing old backend...\r\n2016-06-14 14:41:27.914947 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:41:27.914964 I | etcdserver: recovering alarms...\r\n2016-06-14 14:41:27.920219 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:41:27.920244 I | etcdserver: recovering auth store...\r\n2016-06-14 14:41:27.920261 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:41:27.920273 I | etcdserver: recovering store v2...\r\n2016-06-14 14:41:27.921877 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:41:27.922306 I | etcdserver: recovering cluster configuration...\r\n\r\n2016-06-14 14:42:40.922339 I | mvcc: [DEBUG] compacting 1763190 entries\r\n2016-06-14 14:42:40.924546 I | mvcc: finished scheduled compaction at 9972428 (took 21.693119357s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #11 (normal)\r\n\r\n2016-06-14 14:43:01.364554 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:43:01.371884 I | mvcc: restore compact to 9972428\r\n2016-06-14 14:43:01.618871 I | mvcc: [DEBUG] rebuilding 840009 keys\r\n2016-06-14 14:43:04.013952 I | mvcc: [DEBUG] rebuilt 840009 keys (took 2.395084004s)\r\n2016-06-14 14:43:04.014035 I | mvcc: [DEBUG] restore done for 840009 keys\r\n\r\n2016-06-14 14:43:04.065910 I | rafthttp: receiving database snapshot [index:10580879, from 8e1638a536730aeb] ...\r\n2016-06-14 14:43:04.093350 I | etcdserver: start to snapshot (applied: 10564330, lastsnap: 10443520)\r\n2016-06-14 14:43:04.101590 I | etcdserver: saved snapshot at index 10564330\r\n2016-06-14 14:43:04.102025 I | etcdserver: compacted raft log at 10559330\r\n2016-06-14 14:43:05.978763 I | snap: saved database snapshot to disk [total bytes: 351756288]\r\n2016-06-14 14:43:05.978813 I | rafthttp: received and saved database snapshot [index: 10580879, from: 8e1638a536730aeb] successfully\r\n2016-06-14 14:43:05.978975 I | raft: 8761235f5076cdf [commit: 10566613, lastindex: 10566613, lastterm: 73] starts to restore snapshot [index: 10580879, term: 73]\r\n2016-06-14 14:43:05.979014 I | raft: log [committed=10566613, applied=10566613, unstable.offset=10566614, len(unstable.Entries)=0] starts to restore snapshot [index: 10580879, term: 73]\r\n2016-06-14 14:43:05.979055 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 10580880, match = 10580879, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:43:05.979073 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 10580880, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:43:05.979089 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 10580880, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:43:05.979099 I | raft: 8761235f5076cdf [commit: 10580879] restored snapshot [index: 10580879, term: 73]\r\n2016-06-14 14:43:05.979228 I | etcdserver: applying snapshot at index 10564330...\r\n2016-06-14 14:43:05.982478 I | etcdserver: raft applied incoming snapshot at index 10580879\r\n2016-06-14 14:43:06.009164 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:43:06.009227 I | mvcc: restore compact to 9972428\r\n2016-06-14 14:43:06.249753 I | mvcc: [DEBUG] rebuilding 856553 keys\r\n2016-06-14 14:43:09.482455 I | mvcc: [DEBUG] rebuilt 856553 keys (took 3.232697642s)\r\n2016-06-14 14:43:09.482498 I | mvcc: [DEBUG] restore done for 856553 keys\r\n2016-06-14 14:43:09.482510 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:43:09.482520 I | etcdserver: recovering lessor...\r\n2016-06-14 14:43:09.482662 I | etcdserver: closing old backend...\r\n2016-06-14 14:43:09.492393 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:43:09.492422 I | etcdserver: recovering alarms...\r\n2016-06-14 14:43:09.496091 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:43:09.496115 I | etcdserver: recovering auth store...\r\n2016-06-14 14:43:09.496134 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:43:09.496144 I | etcdserver: recovering store v2...\r\n2016-06-14 14:43:09.497713 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:43:09.497732 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:43:09.497854 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:43:09.497865 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:43:09.497872 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:43:09.497883 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:43:09.497897 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:43:09.497903 I | etcdserver: removing old peers from network...\r\n2016-06-14 14:43:09.497911 I | rafthttp: stopping peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:44:28.929311 I | mvcc: [DEBUG] compacting 1643750 entries\r\n2016-06-14 14:44:28.938553 I | mvcc: finished scheduled compaction at 11366177 (took 20.052338155s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #12 (normal)\r\n\r\n2016-06-14 14:44:49.664013 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:44:49.670964 I | mvcc: restore compact to 11366177\r\n2016-06-14 14:44:49.935553 I | mvcc: [DEBUG] rebuilding 796612 keys\r\n2016-06-14 14:44:52.135750 I | mvcc: [DEBUG] rebuilt 796612 keys (took 2.200162493s)\r\n2016-06-14 14:44:52.135841 I | mvcc: [DEBUG] restore done for 796612 keys\r\n2016-06-14 14:44:52.143404 I | rafthttp: starting peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:44:52.157789 I | rafthttp: receiving database snapshot [index:11937813, from cdde8566ef67fec3] ...\r\n2016-06-14 14:44:52.271000 I | etcdserver: start to snapshot (applied: 11914900, lastsnap: 11797869)\r\n2016-06-14 14:44:52.279507 I | etcdserver: saved snapshot at index 11914900\r\n2016-06-14 14:44:52.280058 I | etcdserver: compacted raft log at 11909900\r\n2016-06-14 14:44:54.050835 I | snap: saved database snapshot to disk [total bytes: 351571968]\r\n2016-06-14 14:44:54.050887 I | rafthttp: received and saved database snapshot [index: 11937813, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:44:54.051048 I | raft: 8761235f5076cdf [commit: 11917253, lastindex: 11917253, lastterm: 82] starts to restore snapshot [index: 11937813, term: 82]\r\n2016-06-14 14:44:54.051080 I | raft: log [committed=11917253, applied=11917253, unstable.offset=11917254, len(unstable.Entries)=0] starts to restore snapshot [index: 11937813, term: 82]\r\n2016-06-14 14:44:54.051118 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 11937814, match = 11937813, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:44:54.051129 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 11937814, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:44:54.051140 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 11937814, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:44:54.051147 I | raft: 8761235f5076cdf [commit: 11937813] restored snapshot [index: 11937813, term: 82]\r\n2016-06-14 14:44:54.051299 I | etcdserver: applying snapshot at index 11914900...\r\n2016-06-14 14:44:54.054498 I | etcdserver: raft applied incoming snapshot at index 11937813\r\n2016-06-14 14:44:54.091000 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:44:54.091161 I | mvcc: restore compact to 11366177\r\n2016-06-14 14:44:54.399359 I | mvcc: [DEBUG] rebuilding 819520 keys\r\n2016-06-14 14:44:56.773488 I | wal: segmented wal file agent.etcd/member/wal/000000000000001d-0000000000b7329b.wal is created\r\n2016-06-14 14:44:57.209537 I | mvcc: [DEBUG] rebuilt 819520 keys (took 2.818796118s)\r\n2016-06-14 14:44:57.209584 I | mvcc: [DEBUG] restore done for 819520 keys\r\n2016-06-14 14:44:57.209597 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:44:57.209610 I | etcdserver: recovering lessor...\r\n2016-06-14 14:44:57.209731 I | etcdserver: closing old backend...\r\n2016-06-14 14:44:57.214366 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:44:57.214390 I | etcdserver: recovering alarms...\r\n2016-06-14 14:44:57.223390 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:44:57.223420 I | etcdserver: recovering auth store...\r\n2016-06-14 14:44:57.223440 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:44:57.223448 I | etcdserver: recovering store v2...\r\n2016-06-14 14:44:57.226042 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:44:57.226066 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:44:57.226189 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:44:57.226216 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:44:57.226229 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:44:57.226242 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:44:57.226262 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:44:57.226272 I | etcdserver: removing old peers from network...\r\n2016-06-14 14:44:57.226283 I | rafthttp: stopping peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:46:13.171579 I | mvcc: [DEBUG] compacting 1517089 entries\r\n2016-06-14 14:46:13.174753 I | mvcc: finished scheduled compaction at 12633265 (took 18.71358284s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #13 (normal)\r\n\r\n2016-06-14 14:46:21.478611 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:46:21.487110 I | mvcc: restore compact to 12633265\r\n2016-06-14 14:46:21.795121 I | mvcc: [DEBUG] rebuilding 609773 keys\r\n2016-06-14 14:46:23.625149 I | mvcc: [DEBUG] rebuilt 609773 keys (took 1.830025026s)\r\n2016-06-14 14:46:23.625223 I | mvcc: [DEBUG] restore done for 609773 keys\r\n2016-06-14 14:46:23.633037 I | rafthttp: starting peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:46:23.650056 I | rafthttp: receiving database snapshot [index:13034702, from 8e1638a536730aeb] ...\r\n2016-06-14 14:46:25.550021 I | snap: saved database snapshot to disk [total bytes: 351756288]\r\n2016-06-14 14:46:25.550069 I | rafthttp: received and saved database snapshot [index: 13034702, from: 8e1638a536730aeb] successfully\r\n2016-06-14 14:46:25.550208 I | raft: 8761235f5076cdf [commit: 12998482, lastindex: 12998482, lastterm: 88] starts to restore snapshot [index: 13034702, term: 88]\r\n2016-06-14 14:46:25.550252 I | raft: log [committed=12998482, applied=12998482, unstable.offset=12998483, len(unstable.Entries)=0] starts to restore snapshot [index: 13034702, term: 88]\r\n2016-06-14 14:46:25.550279 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 13034703, match = 13034702, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:46:25.550293 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 13034703, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:46:25.550302 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 13034703, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:46:25.550309 I | raft: 8761235f5076cdf [commit: 13034702] restored snapshot [index: 13034702, term: 88]\r\n2016-06-14 14:46:25.550417 I | etcdserver: applying snapshot at index 12992383...\r\n2016-06-14 14:46:25.553602 I | etcdserver: raft applied incoming snapshot at index 13034702\r\n2016-06-14 14:46:25.581556 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:46:25.581632 I | mvcc: restore compact to 12633265\r\n2016-06-14 14:46:25.807949 I | mvcc: [DEBUG] rebuilding 649136 keys\r\n2016-06-14 14:46:28.049381 I | mvcc: [DEBUG] rebuilt 649136 keys (took 2.241435139s)\r\n2016-06-14 14:46:28.049440 I | mvcc: [DEBUG] restore done for 649136 keys\r\n2016-06-14 14:46:28.049451 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:46:28.049461 I | etcdserver: recovering lessor...\r\n2016-06-14 14:46:28.049551 I | etcdserver: closing old backend...\r\n2016-06-14 14:46:28.058948 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:46:28.058997 I | etcdserver: recovering alarms...\r\n2016-06-14 14:46:28.064542 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:46:28.064577 I | etcdserver: recovering auth store...\r\n2016-06-14 14:46:28.064598 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:46:28.064620 I | etcdserver: recovering store v2...\r\n2016-06-14 14:46:28.066685 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:46:28.066711 I | etcdserver: recovering cluster configuration...\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #14 (normal)\r\n\r\n2016-06-14 14:46:38.039101 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:46:38.046457 I | mvcc: restore compact to 12633265\r\n2016-06-14 14:46:38.682943 I | mvcc: [DEBUG] rebuilding 777381 keys\r\n2016-06-14 14:46:41.025321 I | mvcc: [DEBUG] rebuilt 777381 keys (took 2.342376888s)\r\n2016-06-14 14:46:41.025389 I | mvcc: [DEBUG] restore done for 777381 keys\r\n\r\n2016-06-14 14:46:41.076605 I | rafthttp: receiving database snapshot [index:13239916, from cdde8566ef67fec3] ...\r\n2016-06-14 14:46:42.962091 I | snap: saved database snapshot to disk [total bytes: 351571968]\r\n2016-06-14 14:46:42.962154 I | rafthttp: received and saved database snapshot [index: 13239916, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:46:42.962321 I | raft: 8761235f5076cdf [commit: 13163048, lastindex: 13163048, lastterm: 89] starts to restore snapshot [index: 13239916, term: 89]\r\n2016-06-14 14:46:42.962380 I | raft: log [committed=13163048, applied=13163048, unstable.offset=13163049, len(unstable.Entries)=0] starts to restore snapshot [index: 13239916, term: 89]\r\n2016-06-14 14:46:42.962418 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 13239917, match = 13239916, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:46:42.962431 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 13239917, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:46:42.962451 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 13239917, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:46:42.962468 I | raft: 8761235f5076cdf [commit: 13239916] restored snapshot [index: 13239916, term: 89]\r\n2016-06-14 14:46:42.962619 I | etcdserver: applying snapshot at index 13158725...\r\n2016-06-14 14:46:42.965540 I | etcdserver: raft applied incoming snapshot at index 13239916\r\n2016-06-14 14:46:42.989984 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:46:42.990047 I | mvcc: restore compact to 12633265\r\n2016-06-14 14:46:43.355400 I | mvcc: [DEBUG] rebuilding 854314 keys\r\n2016-06-14 14:46:45.303492 I | wal: segmented wal file agent.etcd/member/wal/0000000000000020-0000000000cb23e6.wal is created\r\n2016-06-14 14:46:46.455059 I | mvcc: [DEBUG] rebuilt 854314 keys (took 3.108684972s)\r\n2016-06-14 14:46:46.455103 I | mvcc: [DEBUG] restore done for 854314 keys\r\n2016-06-14 14:46:46.455114 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:46:46.455126 I | etcdserver: recovering lessor...\r\n2016-06-14 14:46:46.455264 I | etcdserver: closing old backend...\r\n2016-06-14 14:46:46.464876 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:46:46.464904 I | etcdserver: recovering alarms...\r\n2016-06-14 14:46:46.468627 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:46:46.468649 I | etcdserver: recovering auth store...\r\n2016-06-14 14:46:46.468663 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:46:46.468676 I | etcdserver: recovering store v2...\r\n2016-06-14 14:46:46.470545 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:46:46.470563 I | etcdserver: recovering cluster configuration...\r\n\r\n2016-06-14 14:47:55.867440 I | mvcc: [DEBUG] compacting 1520937 entries\r\n2016-06-14 14:47:55.868209 I | mvcc: finished scheduled compaction at 13904201 (took 18.808697934s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #15 (normal)\r\n\r\n2016-06-14 14:48:11.097502 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:48:11.105233 I | mvcc: restore compact to 13904201\r\n2016-06-14 14:48:11.371685 I | mvcc: [DEBUG] rebuilding 636806 keys\r\n2016-06-14 14:48:13.295483 I | mvcc: [DEBUG] rebuilt 636806 keys (took 1.923831194s)\r\n2016-06-14 14:48:13.295554 I | mvcc: [DEBUG] restore done for 636806 keys\r\n\r\n2016-06-14 14:48:13.331365 I | raft: raft.node: 8761235f5076cdf elected leader cdde8566ef67fec3 at term 97\r\n2016-06-14 14:48:13.341473 I | rafthttp: receiving database snapshot [index:14306847, from cdde8566ef67fec3] ...\r\n2016-06-14 14:48:15.205549 I | snap: saved database snapshot to disk [total bytes: 351571968]\r\n2016-06-14 14:48:15.205602 I | rafthttp: received and saved database snapshot [index: 14306847, from: cdde8566ef67fec3] successfully\r\n2016-06-14 14:48:15.205768 I | raft: 8761235f5076cdf [commit: 14295337, lastindex: 14295337, lastterm: 97] starts to restore snapshot [index: 14306847, term: 97]\r\n2016-06-14 14:48:15.205804 I | raft: log [committed=14295337, applied=14295337, unstable.offset=14295338, len(unstable.Entries)=0] starts to restore snapshot [index: 14306847, term: 97]\r\n2016-06-14 14:48:15.205827 I | raft: 8761235f5076cdf restored progress of 8761235f5076cdf [next = 14306848, match = 14306847, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:48:15.205841 I | raft: 8761235f5076cdf restored progress of 8e1638a536730aeb [next = 14306848, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:48:15.205849 I | raft: 8761235f5076cdf restored progress of cdde8566ef67fec3 [next = 14306848, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]\r\n2016-06-14 14:48:15.205856 I | raft: 8761235f5076cdf [commit: 14306847] restored snapshot [index: 14306847, term: 97]\r\n2016-06-14 14:48:15.205981 I | etcdserver: applying snapshot at index 14285417...\r\n2016-06-14 14:48:15.209112 I | etcdserver: raft applied incoming snapshot at index 14306847\r\n2016-06-14 14:48:15.266966 I | etcdserver: restoring mvcc store...\r\n2016-06-14 14:48:15.267048 I | mvcc: restore compact to 13904201\r\n2016-06-14 14:48:15.521456 I | mvcc: [DEBUG] rebuilding 650129 keys\r\n2016-06-14 14:48:17.961605 I | mvcc: [DEBUG] rebuilt 650129 keys (took 2.440142921s)\r\n2016-06-14 14:48:17.961655 I | mvcc: [DEBUG] restore done for 650129 keys\r\n2016-06-14 14:48:17.961667 I | etcdserver: finished restoring mvcc store\r\n2016-06-14 14:48:17.961677 I | etcdserver: recovering lessor...\r\n2016-06-14 14:48:17.961828 I | etcdserver: closing old backend...\r\n2016-06-14 14:48:17.965836 I | etcdserver: finished recovering lessor\r\n2016-06-14 14:48:17.965856 I | etcdserver: recovering alarms...\r\n2016-06-14 14:48:17.969301 I | etcdserver: finished recovering alarms\r\n2016-06-14 14:48:17.969324 I | etcdserver: recovering auth store...\r\n2016-06-14 14:48:17.969339 I | etcdserver: finished recovering auth store\r\n2016-06-14 14:48:17.969344 I | etcdserver: recovering store v2...\r\n2016-06-14 14:48:17.972447 I | etcdserver: finished recovering store v2\r\n2016-06-14 14:48:17.973266 I | etcdserver: recovering cluster configuration...\r\n2016-06-14 14:48:17.973355 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:48:17.973365 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:48:17.973372 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:48:17.973381 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:48:17.973386 I | etcdserver: finished recovering cluster configuration\r\n2016-06-14 14:48:17.973390 I | etcdserver: removing old peers from network...\r\n2016-06-14 14:48:17.973397 I | rafthttp: stopping peer 8e1638a536730aeb...\r\n\r\n2016-06-14 14:49:49.426879 I | mvcc: [DEBUG] compacting 1475685 entries\r\n2016-06-14 14:49:49.429538 I | mvcc: finished scheduled compaction at 15129885 (took 18.536800813s)\r\n\r\n=========================================================================================\r\n\r\nSNAPSHOT CASE #16 (FAILURE, possible LIVE-LOCK)\r\n\r\n----------------------------------------> tester\r\n2016-06-14 14:49:49.736745 I | etcd-tester: [round#14 case#0] recovering failure \"kill all members\"\r\n2016-06-14 14:49:50.741957 W | etcd-tester: #0 setHealthKey error (rpc error: code = 4 desc = context deadline exceeded (10.240.0.13:2379))\r\n...\r\n2016-06-14 14:51:48.932149 W | etcd-tester: #59 setHealthKey error (rpc error: code = 4 desc = context deadline exceeded (10.240.0.13:2379))\r\n2016-06-14 14:51:49.932972 I | etcd-tester: [round#14 case#0] recovery error: rpc error: code = 4 desc = context deadline exceeded (10.240.0.13:2379)\r\n2016-06-14 14:51:49.933052 I | etcd-tester: [round#14 case#0] cleaning up...\r\n\r\n\r\n\r\n----------------------------------------> node1 (10.240.0.13:2379) times out after leader election\r\n2016-06-14 14:49:49.790543 I | etcdserver: name = etcd-0\r\n2016-06-14 14:49:49.790550 I | etcdserver: data dir = agent.etcd\r\n2016-06-14 14:49:49.790560 I | etcdserver: member dir = agent.etcd/member\r\n2016-06-14 14:49:49.790570 I | etcdserver: heartbeat = 100ms\r\n2016-06-14 14:49:49.790578 I | etcdserver: election = 1000ms\r\n2016-06-14 14:49:49.790587 I | etcdserver: snapshot count = 10000\r\n2016-06-14 14:49:49.790617 I | etcdserver: advertise client URLs = http://10.240.0.13:2379\r\n2016-06-14 14:49:50.731336 I | etcdserver: restarting member 8761235f5076cdf in cluster 3955e179eda388f8 at commit index 15478393\r\n2016-06-14 14:49:50.744892 I | raft: 8761235f5076cdf became follower at term 103\r\n2016-06-14 14:49:50.744948 I | raft: newRaft 8761235f5076cdf [peers: [8761235f5076cdf,8e1638a536730aeb,cdde8566ef67fec3], term: 103, commit: 15478393, applied: 14952679, lastindex: 15478462, lastterm: 103]\r\n2016-06-14 14:49:50.967634 I | membership: added member 8761235f5076cdf [http://10.240.0.13:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:49:50.967678 I | membership: added member 8e1638a536730aeb [http://10.240.0.15:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:49:50.967686 I | membership: added member cdde8566ef67fec3 [http://10.240.0.14:2380] to cluster 3955e179eda388f8 from store\r\n2016-06-14 14:49:50.967705 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:49:51.007736 I | mvcc: restore compact to 15129885\r\n2016-06-14 14:49:51.140949 I | mvcc: [DEBUG] rebuilding 595798 keys\r\n2016-06-14 14:49:52.818710 I | mvcc: [DEBUG] rebuilt 595798 keys (took 1.677754601s)\r\n2016-06-14 14:49:52.818776 I | mvcc: [DEBUG] restore done for 595798 keys\r\n2016-06-14 14:49:52.826487 I | rafthttp: starting peer 8e1638a536730aeb...\r\n2016-06-14 14:49:52.826540 I | rafthttp: started HTTP pipelining with peer 8e1638a536730aeb\r\n2016-06-14 14:49:52.826873 I | rafthttp: started streaming with peer 8e1638a536730aeb (writer)\r\n2016-06-14 14:49:52.827022 I | rafthttp: started streaming with peer 8e1638a536730aeb (writer)\r\n2016-06-14 14:49:52.827308 I | rafthttp: started peer 8e1638a536730aeb\r\n2016-06-14 14:49:52.827336 I | rafthttp: added peer 8e1638a536730aeb\r\n2016-06-14 14:49:52.827356 I | rafthttp: starting peer cdde8566ef67fec3...\r\n2016-06-14 14:49:52.827386 I | rafthttp: started streaming with peer 8e1638a536730aeb (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.827474 I | rafthttp: started HTTP pipelining with peer cdde8566ef67fec3\r\n2016-06-14 14:49:52.827615 I | rafthttp: started streaming with peer 8e1638a536730aeb (stream Message reader)\r\n2016-06-14 14:49:52.827804 I | rafthttp: started streaming with peer cdde8566ef67fec3 (writer)\r\n2016-06-14 14:49:52.827897 I | rafthttp: started streaming with peer cdde8566ef67fec3 (writer)\r\n2016-06-14 14:49:52.828334 I | rafthttp: started peer cdde8566ef67fec3\r\n2016-06-14 14:49:52.828360 I | rafthttp: added peer cdde8566ef67fec3\r\n2016-06-14 14:49:52.828374 I | rafthttp: started streaming with peer cdde8566ef67fec3 (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.828456 I | etcdserver: starting server... [version: 3.0.0-beta.0+git, cluster version: 3.0]\r\n2016-06-14 14:49:52.828478 I | rafthttp: started streaming with peer cdde8566ef67fec3 (stream Message reader)\r\n2016-06-14 14:49:52.828925 I | api: enabled capabilities for version 3.0.0\r\n2016-06-14 14:49:52.828988 I | rafthttp: peer 8e1638a536730aeb became active\r\n2016-06-14 14:49:52.829021 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream Message reader)\r\n2016-06-14 14:49:52.829114 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.829556 I | rafthttp: peer cdde8566ef67fec3 became active\r\n2016-06-14 14:49:52.829571 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.829974 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream MsgApp v2 writer)\r\n2016-06-14 14:49:52.830003 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream Message reader)\r\n2016-06-14 14:49:52.830264 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream MsgApp v2 writer)\r\n2016-06-14 14:49:52.830302 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream Message writer)\r\n2016-06-14 14:49:52.830381 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream Message writer)\r\n2016-06-14 14:49:52.854603 I | raft: 8761235f5076cdf [term: 103] received a MsgApp message with higher term from cdde8566ef67fec3 [term: 104]\r\n2016-06-14 14:49:52.854668 I | raft: 8761235f5076cdf became follower at term 104\r\n2016-06-14 14:49:52.881288 I | raft: raft.node: 8761235f5076cdf elected leader cdde8566ef67fec3 at term 104\r\n2016-06-14 14:49:52.906760 I | raft: 8761235f5076cdf [logterm: 104, index: 15478463, vote: 0] rejected vote from cdde8566ef67fec3 [logterm: 103, index: 15478462] at term 104\r\n2016-06-14 14:49:59.854638 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:06.854959 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:13.865341 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:20.865641 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:27.866024 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:34.888010 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:41.888266 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:48.970304 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:50:55.981330 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:03.013196 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:10.018025 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:17.063847 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:24.078617 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:31.078969 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:38.102816 E | etcdserver: publish error: etcdserver: request timed out\r\n2016-06-14 14:51:45.115410 E | etcdserver: publish error: etcdserver: request timed out\r\n\r\n----------------------------------------> node2 becomes the leader\r\n2016-06-14 14:49:49.913465 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:49:49.922648 I | mvcc: restore compact to 15129885\r\n2016-06-14 14:49:50.227340 I | mvcc: [DEBUG] rebuilding 595798 keys\r\n2016-06-14 14:49:51.967092 I | mvcc: [DEBUG] rebuilt 595798 keys (took 1.739751896s)\r\n2016-06-14 14:49:51.967156 I | mvcc: [DEBUG] restore done for 595798 keys\r\n...\r\n2016-06-14 14:49:52.381219 I | rafthttp: peer 8e1638a536730aeb became active\r\n2016-06-14 14:49:52.381262 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.381394 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream Message writer)\r\n2016-06-14 14:49:52.381424 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream Message reader)\r\n2016-06-14 14:49:52.381508 I | rafthttp: established a TCP streaming connection with peer 8e1638a536730aeb (stream MsgApp v2 writer)\r\n2016-06-14 14:49:52.813807 I | raft: cdde8566ef67fec3 is starting a new election at term 103\r\n2016-06-14 14:49:52.813943 I | raft: cdde8566ef67fec3 became candidate at term 104\r\n2016-06-14 14:49:52.813960 I | raft: cdde8566ef67fec3 received vote from cdde8566ef67fec3 at term 104\r\n2016-06-14 14:49:52.813978 I | raft: cdde8566ef67fec3 [logterm: 103, index: 15478462] sent vote request to 8761235f5076cdf at term 104\r\n2016-06-14 14:49:52.813993 I | raft: cdde8566ef67fec3 [logterm: 103, index: 15478462] sent vote request to 8e1638a536730aeb at term 104\r\n2016-06-14 14:49:52.817575 I | raft: cdde8566ef67fec3 received vote from 8e1638a536730aeb at term 104\r\n2016-06-14 14:49:52.817598 I | raft: cdde8566ef67fec3 [quorum:2] has received 2 votes and 0 vote rejections\r\n2016-06-14 14:49:52.817632 I | raft: cdde8566ef67fec3 became leader at term 104\r\n2016-06-14 14:49:52.817647 I | raft: raft.node: cdde8566ef67fec3 elected leader cdde8566ef67fec3 at term 104\r\n2016-06-14 14:49:52.822309 I | etcdserver: published {Name:etcd-1 ClientURLs:[http://10.240.0.14:2379]} to cluster 3955e179eda388f8\r\n2016-06-14 14:49:52.822352 I | etcdmain: ready to serve client requests\r\n2016-06-14 14:49:52.822446 E | etcdmain: failed to notify systemd for readiness: No socket\r\n2016-06-14 14:49:52.822461 E | etcdmain: forgot to set Type=notify in systemd service file?\r\n2016-06-14 14:49:52.822517 N | etcdmain: serving insecure client requests on 10.240.0.14:2379, this is strongly discouraged!\r\n2016-06-14 14:49:52.829234 I | rafthttp: peer 8761235f5076cdf became active\r\n2016-06-14 14:49:52.829260 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream MsgApp v2 writer)\r\n2016-06-14 14:49:52.829713 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.829781 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream Message writer)\r\n2016-06-14 14:49:52.830415 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream Message reader)\r\n2016-06-14 14:49:53.366199 I | etcdserver: start to snapshot (applied: 15487486, lastsnap: 15477477)\r\n2016-06-14 14:49:53.376997 I | etcdserver: saved snapshot at index 15487486\r\n\r\n----------------------------------------> node3\r\n2016-06-14 14:49:50.142015 I | membership: set the cluster version to 3.0 from store\r\n2016-06-14 14:49:50.151493 I | mvcc: restore compact to 15129885\r\n2016-06-14 14:49:50.455863 I | mvcc: [DEBUG] rebuilding 595798 keys\r\n2016-06-14 14:49:52.369828 I | mvcc: [DEBUG] rebuilt 595798 keys (took 1.913913295s)\r\n2016-06-14 14:49:52.369908 I | mvcc: [DEBUG] restore done for 595798 keys\r\n2016-06-14 14:49:52.378485 I | rafthttp: starting peer 8761235f5076cdf...\r\n2016-06-14 14:49:52.378538 I | rafthttp: started HTTP pipelining with peer 8761235f5076cdf\r\n2016-06-14 14:49:52.378876 I | rafthttp: started streaming with peer 8761235f5076cdf (writer)\r\n2016-06-14 14:49:52.378989 I | rafthttp: started streaming with peer 8761235f5076cdf (writer)\r\n2016-06-14 14:49:52.379178 I | rafthttp: started peer 8761235f5076cdf\r\n2016-06-14 14:49:52.379197 I | rafthttp: added peer 8761235f5076cdf\r\n2016-06-14 14:49:52.379209 I | rafthttp: starting peer cdde8566ef67fec3...\r\n2016-06-14 14:49:52.379219 I | rafthttp: started streaming with peer 8761235f5076cdf (stream Message reader)\r\n2016-06-14 14:49:52.379369 I | rafthttp: started streaming with peer 8761235f5076cdf (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.379481 I | rafthttp: started HTTP pipelining with peer cdde8566ef67fec3\r\n2016-06-14 14:49:52.379790 I | rafthttp: started streaming with peer cdde8566ef67fec3 (writer)\r\n2016-06-14 14:49:52.380025 I | rafthttp: started streaming with peer cdde8566ef67fec3 (writer)\r\n2016-06-14 14:49:52.380228 I | rafthttp: started peer cdde8566ef67fec3\r\n2016-06-14 14:49:52.380252 I | rafthttp: added peer cdde8566ef67fec3\r\n2016-06-14 14:49:52.380266 I | rafthttp: started streaming with peer cdde8566ef67fec3 (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.380375 I | etcdserver: starting server... [version: 3.0.0-beta.0+git, cluster version: 3.0]\r\n2016-06-14 14:49:52.380412 I | rafthttp: started streaming with peer cdde8566ef67fec3 (stream Message reader)\r\n2016-06-14 14:49:52.380659 I | api: enabled capabilities for version 3.0.0\r\n2016-06-14 14:49:52.380847 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000e97caf.snap successfully\r\n2016-06-14 14:49:52.380924 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000e9a427.snap successfully\r\n2016-06-14 14:49:52.380940 I | rafthttp: peer cdde8566ef67fec3 became active\r\n2016-06-14 14:49:52.380968 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream Message writer)\r\n2016-06-14 14:49:52.380982 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000e9cb54.snap successfully\r\n2016-06-14 14:49:52.381025 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000e9f266.snap successfully\r\n2016-06-14 14:49:52.381064 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000ea19a4.snap successfully\r\n2016-06-14 14:49:52.381106 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000ea4129.snap successfully\r\n2016-06-14 14:49:52.381131 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream MsgApp v2 writer)\r\n2016-06-14 14:49:52.381166 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000ea685d.snap successfully\r\n2016-06-14 14:49:52.381214 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000ea8f80.snap successfully\r\n2016-06-14 14:49:52.381258 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000eab6ba.snap successfully\r\n2016-06-14 14:49:52.381304 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000eadddb.snap successfully\r\n2016-06-14 14:49:52.381342 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000eb04f8.snap successfully\r\n2016-06-14 14:49:52.381384 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000eb2c0d.snap successfully\r\n2016-06-14 14:49:52.381462 I | fileutil: purged file agent.etcd/member/snap/0000000000000067-0000000000eb5333.snap successfully\r\n2016-06-14 14:49:52.381514 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream Message reader)\r\n2016-06-14 14:49:52.381547 I | rafthttp: established a TCP streaming connection with peer cdde8566ef67fec3 (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.815863 I | raft: 8e1638a536730aeb [term: 103] received a MsgVote message with higher term from cdde8566ef67fec3 [term: 104]\r\n2016-06-14 14:49:52.816147 I | raft: 8e1638a536730aeb became follower at term 104\r\n2016-06-14 14:49:52.816211 I | raft: 8e1638a536730aeb [logterm: 103, index: 15478462, vote: 0] voted for cdde8566ef67fec3 [logterm: 103, index: 15478462] at term 104\r\n2016-06-14 14:49:52.818087 I | raft: raft.node: 8e1638a536730aeb elected leader cdde8566ef67fec3 at term 104\r\n2016-06-14 14:49:52.822813 I | etcdmain: ready to serve client requests\r\n2016-06-14 14:49:52.822930 I | etcdserver: published {Name:etcd-2 ClientURLs:[http://10.240.0.15:2379]} to cluster 3955e179eda388f8\r\n2016-06-14 14:49:52.822980 E | etcdmain: failed to notify systemd for readiness: No socket\r\n2016-06-14 14:49:52.823003 E | etcdmain: forgot to set Type=notify in systemd service file?\r\n2016-06-14 14:49:52.823046 N | etcdmain: serving insecure client requests on 10.240.0.15:2379, this is strongly discouraged!\r\n2016-06-14 14:49:52.828832 I | rafthttp: peer 8761235f5076cdf became active\r\n2016-06-14 14:49:52.828860 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream Message writer)\r\n2016-06-14 14:49:52.829044 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream MsgApp v2 writer)\r\n2016-06-14 14:49:52.829972 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream MsgApp v2 reader)\r\n2016-06-14 14:49:52.830512 I | rafthttp: established a TCP streaming connection with peer 8761235f5076cdf (stream Message reader)\r\n2016-06-14 14:49:53.066432 I | etcdserver: start to snapshot (applied: 15482432, lastsnap: 15472397)\r\n2016-06-14 14:49:53.101370 I | etcdserver: saved snapshot at index 15482432\r\n2016-06-14 14:49:53.101642 I | etcdserver: compacted raft log at 15477432\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/coreos/etcd/issues/comments/226877944","html_url":"https://github.com/coreos/etcd/issues/5679#issuecomment-226877944","issue_url":"https://api.github.com/repos/coreos/etcd/issues/5679","id":226877944,"user":{"login":"xiang90","id":4479947,"avatar_url":"https://avatars.githubusercontent.com/u/4479947?v=3","gravatar_id":"","url":"https://api.github.com/users/xiang90","html_url":"https://github.com/xiang90","followers_url":"https://api.github.com/users/xiang90/followers","following_url":"https://api.github.com/users/xiang90/following{/other_user}","gists_url":"https://api.github.com/users/xiang90/gists{/gist_id}","starred_url":"https://api.github.com/users/xiang90/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/xiang90/subscriptions","organizations_url":"https://api.github.com/users/xiang90/orgs","repos_url":"https://api.github.com/users/xiang90/repos","events_url":"https://api.github.com/users/xiang90/events{/privacy}","received_events_url":"https://api.github.com/users/xiang90/received_events","type":"User","site_admin":false},"created_at":"2016-06-17T20:49:08Z","updated_at":"2016-06-17T20:49:08Z","body":"This is fixed by #5692."}}
{"actor":{"display_login":"xiang90"}}