{"action":"created","issue":{"url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6108","labels_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6108/labels{/name}","comments_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6108/comments","events_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6108/events","html_url":"https://github.com/hazelcast/hazelcast/issues/6108","id":104306068,"number":6108,"title":"Missed heartbeat caused permanent cluster inconsistency","user":{"login":"torkeld","id":6555813,"avatar_url":"https://avatars.githubusercontent.com/u/6555813?v=3","gravatar_id":"","url":"https://api.github.com/users/torkeld","html_url":"https://github.com/torkeld","followers_url":"https://api.github.com/users/torkeld/followers","following_url":"https://api.github.com/users/torkeld/following{/other_user}","gists_url":"https://api.github.com/users/torkeld/gists{/gist_id}","starred_url":"https://api.github.com/users/torkeld/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/torkeld/subscriptions","organizations_url":"https://api.github.com/users/torkeld/orgs","repos_url":"https://api.github.com/users/torkeld/repos","events_url":"https://api.github.com/users/torkeld/events{/privacy}","received_events_url":"https://api.github.com/users/torkeld/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":{"login":"tombujok","id":1047469,"avatar_url":"https://avatars.githubusercontent.com/u/1047469?v=3","gravatar_id":"","url":"https://api.github.com/users/tombujok","html_url":"https://github.com/tombujok","followers_url":"https://api.github.com/users/tombujok/followers","following_url":"https://api.github.com/users/tombujok/following{/other_user}","gists_url":"https://api.github.com/users/tombujok/gists{/gist_id}","starred_url":"https://api.github.com/users/tombujok/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tombujok/subscriptions","organizations_url":"https://api.github.com/users/tombujok/orgs","repos_url":"https://api.github.com/users/tombujok/repos","events_url":"https://api.github.com/users/tombujok/events{/privacy}","received_events_url":"https://api.github.com/users/tombujok/received_events","type":"User","site_admin":false},"milestone":null,"comments":6,"created_at":"2015-09-01T16:35:26Z","updated_at":"2015-09-03T09:00:55Z","closed_at":null,"body":"*I apologize for the long description.*\r\n\r\nTL;DR: This happened in our production environment a week ago. There was a short network outage that caused a missed heartbeat between the master node and one of the members. That triggered a series of events that eventually left the cluster in a state where the different nodes had different masters and different members list. The result was operations that failed with CallerNotMemberException and WrongTargetException.\r\n\r\nHazelcast version used: 3.2.6\r\n\r\n### Full analysis of the situation:\r\n\r\n#### Nodes\r\nCS1: IP 10.181.123.80, AZ 1b\r\nCS2: IP 10.113.170.130, AZ 1e\r\nCS3: IP 10.232.137.233, AZ 1d, initially master\r\nCS4: IP 10.166.134.204, AZ 1d\r\n\r\n#### Sequence of events\r\n![analysis of incident 86685349888](https://cloud.githubusercontent.com/assets/6555813/9610112/608800da-508c-11e5-8892-319c72d2f3f7.jpg)\r\n\r\n#### Analysis\r\nHazelcast nodes send heartbeats every 5s. If a node doesn’t receive a heartbeat within 10s it will remove that node from the cluster.\r\nIn this scenario, CS3, who is the master of the cluster, doesn’t get a heartbeat from CS2 in 10s so it removes it from the cluster. CS2 on the other hand does get the heartbeat from CS3 so it doesn’t remove CS3. At this point CS2 still has all the other members in its cluster state, but the other members don’t have CS2. Now, the other members try to reconnect to CS2 (see SplitBrainHandler.java). CS3 sees that CS2 has more members than itself (4 vs 3) it decides to merge with CS2.\r\n\r\nWhen CS3 tries to join CS2’s cluster, CS2 sees that CS3 is still in its member list so it first removes it from its cluster. Since CS2 was master CS3 will assign a new master, CS4.\r\n```\r\nWARN  20:43:28.539  [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] New join request has been received from an existing endpoint!\r\n => Member [10.232.137.233]:5701 Removing old member and processing join request...\r\nINFO  20:43:28.539  [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Master Address[10.232.137.233]:5701 left the cluster. Assigning new master Member [10.166.134.204]:5701\r\n```\r\nCS2 tells CS3 that CS4 is the new master, and when CS4 joins CS2 does the same thing with CS4 and now promotes itself to master.\r\n```\r\nWARN  20:43:28.630 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] New join request has been received from an existing endpoint! => Member [10.166.134.204]:5701 Removing old member and processing join request...\r\nINFO  20:43:28.630 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Master Address[10.166.134.204]:5701 left the cluster. Assigning new master Member [10.113.170.130]:5701 this\r\n```\r\nFor some reason CS3 is not informed that CS2 is now master and ignores the master responses from CS2 as it thinks CS4 is master.\r\n```\r\nWARN  20:43:31.540 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Ignoring master response from Address[10.113.170.130]:5701, since this node has an active master: Address[10.166.134.204]:5701\r\n\r\nSimilarly, CS1 didn’t get notified when master changed and also ignores the master responses from CS2 as it thinks CS3 is master.\r\nWARN  20:43:31.521 [10.181.123.80]:5701 [prod-voice-conference-state-service] [3.2.6] Ignoring master response from Address[10.113.170.130]:5701, since this node has an active master: Address[10.232.137.233]:5701\r\n```\r\nCS2 seems to get stuck merging at this point and keeps printing the following message, while all other members are done with the merge.\r\n```\r\nINFO  20:43:37.777 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Re-partitioning cluster data... Migration queue size: 203\r\nINFO  20:43:43.959 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Remaining migration tasks in queue => 134\r\nINFO  20:43:58.959 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Remaining migration tasks in queue => 134\r\nINFO  20:44:13.959 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Remaining migration tasks in queue => 134\r\nThis is probably because CS3 doesn’t think that CS2 is the master and ignores the migration tasks.\r\nWARN  20:43:51.437 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Address[10.181.123.80]:5701 has sent MasterConfirmation, but this node is not master!\r\n```\r\nAt this point all nodes have 4 nodes in their member lists but a different view of who is master. HTTP requests at this point are being served properly (although there might have been some data inconsistency), entry processors are being processed by all nodes.\r\n\r\nAbout 8 minutes later (500 s) CS2 removes CS1 from the cluster since it hasn’t received any master confirmation in 500 seconds (CS1 has been sending those to CS3 the whole time). It instructs CS3 and CS4 to remove CS1, but CS3 ignores this since it thinks that CS4 is master.\r\n```\r\nWARN  20:51:48.867 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Received a ClusterRuntimeState, but its sender doesn't seem to be master! => Sender: Address[10.113.170.130]:5701, Master: Address[10.166.134.204]:5701! (Ignore if master node has changed recently.)\r\n```\r\n2s later CS2 reconnects with CS1 and since CS1 has more members in its list (4 vs 3) CS2 will merge with CS1, and hence CS2 will now consider CS3 as master (same as CS1). However, CS2 doesn’t add CS1 to its members list. \r\n```\r\nINFO  20:52:00.822 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Address[10.113.170.130]:5701 is merging to Address[10.181.123.80]:5701, because : joinRequest.getMemberCount() > currentMemberCount [4 > 3]\r\n```\r\nCS4 also merges with CS1 as instructed by CS2.\r\n```\r\nWARN  20:52:00.827 [10.166.134.204]:5701 [prod-voice-conference-state-service] [3.2.6] Address[10.166.134.204]:5701 is merging to Address[10.181.123.80]:5701, because: instructed by master Address[10.113.170.130]:5701\r\n```\r\nCS4 “re-joins” with CS3. This causes CS3 to remove CS4 and assigning CS2 as master:\r\n```\r\nWARN  20:52:02.946 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] New join request has been received from an existing endpoint! => Member [10.166.134.204]:5701 Removing old member and processing join request...\r\nERROR 20:52:02.946 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Old master Address[10.166.134.204]:5701 is dead but the first of member list is a different member Member [10.113.170.130]:5701!\r\nINFO  20:52:02.946 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Master Address[10.166.134.204]:5701 left the cluster. Assigning new master Member [10.113.170.130]:5701\r\nINFO  20:52:02.946 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Removing Member [10.166.134.204]:5701\r\n```\r\nSimilarly, CS2 re-joins with CS3, which causes CS3 to remove CS2 and assigning CS1 as master.\r\n```\r\nWARN  20:52:02.998 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] New join request has been received from an existing endpoint! => Member [10.113.170.130]:5701 Removing old member and processing join request...\r\nINFO  20:52:02.998 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Master Address[10.113.170.130]:5701 left the cluster. Assigning new master Member [10.181.123.80]:5701\r\nINFO  20:52:02.998 [10.232.137.233]:5701 [prod-voice-conference-state-service] [3.2.6] Removing Member [10.113.170.130]:5701\r\n```\r\nCS1 now thinks CS2 is master and starts sending master responses to it (why??):\r\n```\r\nWARN  20:52:03.008 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Ignoring master response from Address[10.181.123.80]:5701, since this node has an active master: Address[10.232.137.233]:5701\r\n```\r\nFrom this point HTTP traffic starts to fail since CS3 and CS4 rejects all entry processors from CS1 as they are not in their members lists.\r\n\r\nCS2 and CS4 keeps trying to rejoin with CS3 but fails:\r\n```\r\nWARN  20:54:39.023 [10.113\r\n.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Couldn't join to the master : Address[10.232.137.233]:5701\r\nWARN  20:54:39.023 [10.113\r\n.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Failed to connect, node joined= false, allConnected= false to all other me\r\nmbers after 0 seconds.\r\nWARN  20:54:39.023 [10.113\r\n.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Rebooting after 10 seconds.\r\n```\r\nAnd eventually gives up and sets itself as master:\r\n```\r\nWARN  20:55:16.029 [10.113.170.130]:5701 [prod-voice-conference-state-service] [3.2.6] Join try count exceed limit, setting this node as master!\r\n```"},"comment":{"url":"https://api.github.com/repos/hazelcast/hazelcast/issues/comments/137384173","html_url":"https://github.com/hazelcast/hazelcast/issues/6108#issuecomment-137384173","issue_url":"https://api.github.com/repos/hazelcast/hazelcast/issues/6108","id":137384173,"user":{"login":"tombujok","id":1047469,"avatar_url":"https://avatars.githubusercontent.com/u/1047469?v=3","gravatar_id":"","url":"https://api.github.com/users/tombujok","html_url":"https://github.com/tombujok","followers_url":"https://api.github.com/users/tombujok/followers","following_url":"https://api.github.com/users/tombujok/following{/other_user}","gists_url":"https://api.github.com/users/tombujok/gists{/gist_id}","starred_url":"https://api.github.com/users/tombujok/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tombujok/subscriptions","organizations_url":"https://api.github.com/users/tombujok/orgs","repos_url":"https://api.github.com/users/tombujok/repos","events_url":"https://api.github.com/users/tombujok/events{/privacy}","received_events_url":"https://api.github.com/users/tombujok/received_events","type":"User","site_admin":false},"created_at":"2015-09-03T09:00:55Z","updated_at":"2015-09-03T09:00:55Z","body":"Thx for the logs. We are looking into it, but it may take us some time to make any statement, so plz state tuned. "}}