GMS Join fails after node reconnects
Brought to you by:
belaban
Menu
▾
▴
Hi,
I'm using JGroups 4.0.15.Final to implement a cluster application. Everything works fine when I startup the two nodes, they got connected and start working. But when I kill (SIGKILL) one node and restart it, the nodes wont join together anymore. I've tried to find the problem for hours but I just can't find it. Sometimes the nodes got connected again after several connection attempts but that can take from few minutes to over an hour. I think it has something to do with the reincarnation problem but I'm not sure.
This is my current configuration:
public class JGroupsConfiguration { final Protocol[] PROTOCOL_STACK = { new TCP() .setValue("bind_port", EngineConfiguration.get().clusterSrcPort().get()) .setValue("max_bundle_size", 64000) .setValue("sock_conn_timeout", 300) .setValue("thread_pool_min_threads", 0) .setValue("thread_pool_max_threads", 20) .setValue("thread_pool_keep_alive_time", 3000), new TCPPING() .setValue("async_discovery", false) .setValue("port_range", 0) .setValue("send_cache_on_join", true) .setValue("return_entire_cache", true), new MERGE3() .setValue("min_interval", 10000) .setValue("max_interval", 30000), new FD() .setValue("timeout", 3000) .setValue("max_tries", 3), new VERIFY_SUSPECT() .setValue("timeout", 1500), new BARRIER(), new NAKACK2() .setValue("use_mcast_xmit", false) .setValue("discard_delivered_msgs", true), new UNICAST3() // Disables retransmitting of queued messages to reconnected nodes. .setValue("max_retransmit_time", 0), new STABLE() .setValue("desired_avg_gossip", 50000) .setValue("max_bytes", 4000000), new GMS() .setValue("print_local_addr", true) .setValue("join_timeout", 2000), new FRAG3() .setValue("frag_size", 60000), new STATE() }; }I've attached the logs of the two nodes (NODE_1.log, NODE_2.log) with enabled trace on org.jgroups.protocols. On the NODE_2 the address of the NODE_1 is included in the TCPPING.initial_hosts.
Note: Their is one specialty in my application because I'm using a custom socket factory for the TCP protocol. This factory creates encrypted sockets with some special requirements. But the connections seem to be fine and the socket works. The only thing I noticed is that after NODE_2 was verified as dead their are still connection attempts on its socket by the TCP protocol (see NODE_1.log line 142).
I hope anyone can help me with this because I'm out of ideas.
Last edit: Jürgen Westerkamp 2019-01-05
Last edit: Jürgen Westerkamp 2019-01-05
Hi,
I still try to find a solution for this problem. I'm currently analyzing the TRACE logs for the TCP protocol but still can't point out the reason why the two nodes need several minutes to merge again.
When I restart the NODE_2 while both (NODE_1 = 1.1.1.1, NODE_2 = 1.1.1.2) are connected and everything is working fine. On both sides I see that a connection is established:
NODE_1:
NODE_2:
After this its like both are in a loop to handle out something. While NODE_2 is trying to join (sending JOIN(NODE_2) to NODE_1) the NODE_1 doesn't seem to notice it and I don't see the GMS protocol involved in the LOG of NODE_1. I also see a lot of messages asking for the first sequence number over and over again (UNICAST3 NODE_2 --> SEND_FIRST_SEQNO(NODE_1 (flags=1)) | (Log4J2LogImpl.java:56) ). This is going on for a while (the time varies from few seconds to sometimes hours) until the join / merge suddenly works:
NODE_1:
NODE_2:
2019-01-17 10:11:36.547 [jgrp-174 | ] TRACE UNICAST3 - NODE_2 --> SEND_FIRST_SEQNO(NODE_1 (flags=1)) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:36.547 [jgrp-174 | ] TRACE TCP - NODE_2: sending msg to NODE_1 (flags=1), src=NODE_2, headers are UNICAST3: SEND_FIRST_SEQNO, seqno=0, ts=581, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:36.550 [jgrp-174 | ] TRACE TCP - NODE_2: received message batch of 1 messages from NODE_1 (flags=1) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:36.550 [jgrp-174 | ] TRACE UNICAST3 - NODE_2: created receiver window for NODE_1 (flags=1) at seqno=#19725 for conn-id=0 | (Log4J2LogImpl.java:56) 2019-01-17 10:11:36.553 [jgrp-174 | ] TRACE UNICAST3 - NODE_2 <-- DATA(NODE_1 (flags=1): #19725 - #19725) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:36.553 [jgrp-174 | ] TRACE UNICAST3 - NODE_2: delivering #19725 - #19725 (1 messages) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:36.713 [jgrp-174 | ] TRACE UNICAST3 - NODE_2 --> ACK(NODE_1 (flags=1): #19725) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:36.713 [jgrp-174 | ] TRACE TCP - NODE_2: sending msg to NODE_1 (flags=1), src=NODE_2, headers are UNICAST3: ACK, seqno=19725, ts=582, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.296 [jgrp-174 | ] TRACE MERGE3 - NODE_2: merge participants are [NODE_2, NODE_1 (flags=1)] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.296 [jgrp-174 | ] TRACE TCP - NODE_2: sending msg to NODE_1 (flags=1), src=NODE_2, headers are MERGE3: VIEW_REQ: , logical_name=null, physical_addr=null, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.299 [jgrp-177 | ] TRACE TCP - NODE_2: received [dst: NODE_2, src: NODE_1 (flags=1) (2 headers), size=67 bytes, flags=INTERNAL], headers are MERGE3: VIEW_RSP: , logical_name=null, physical_addr=null, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.299 [jgrp-174 | ] DEBUG GMS - NODE_2: I will be the merge leader. Starting the merge task. Views: {NODE_1 (flags=1)=[NODE_1 (flags=1)|3] (2) [NODE_1 (flags=1), NODE_2], NODE_2=MergeView::[NODE_2|24] (1) [NODE_2], 1 subgroups: [NODE_2|23] (1) [NODE_2]} | (Log4J2LogImpl.java:71) 2019-01-17 10:11:37.300 [MergeTas | ] DEBUG STABLE - suspending message garbage collection | (Log4J2LogImpl.java:66) 2019-01-17 10:11:37.300 [MergeTas | ] DEBUG STABLE - NODE_2: resume task started, max_suspend_time=220000 | (Log4J2LogImpl.java:71) 2019-01-17 10:11:37.300 [MergeTas | ] DEBUG GMS - NODE_2: merge task NODE_2::22 started with 2 participants | (Log4J2LogImpl.java:71) 2019-01-17 10:11:37.300 [MergeTas | ] TRACE GMS - NODE_2: sending MERGE_REQ to [NODE_1 (flags=1), NODE_2] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.300 [MergeTas | ] TRACE UNICAST3 - NODE_2 --> DATA(NODE_1 (flags=1): #32, conn_id=0) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.300 [MergeTas | ] TRACE TCP - NODE_2: sending msg to NODE_1 (flags=1), src=NODE_2, headers are GMS: GmsHeader[MERGE_REQ]: merge_id=NODE_2::22, UNICAST3: DATA, seqno=32, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.301 [MergeTas | ] TRACE UNICAST3 - NODE_2 --> DATA(NODE_2: #64, conn_id=1) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.301 [MergeTas | ] TRACE TCP - NODE_2: sending msg to NODE_2, src=NODE_2, headers are GMS: GmsHeader[MERGE_REQ]: merge_id=NODE_2::22, UNICAST3: DATA, seqno=64, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.301 [MergeTas | ] TRACE TCP - NODE_2: looping back message [dst: NODE_2, src: NODE_2 (3 headers), size=22 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[MERGE_REQ]: merge_id=NODE_2::22, UNICAST3: DATA, seqno=64, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.301 [jgrp-174 | ] TRACE TCP - NODE_2: received [dst: NODE_2, src: NODE_2 (3 headers), size=22 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[MERGE_REQ]: merge_id=NODE_2::22, UNICAST3: DATA, seqno=64, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.302 [jgrp-174 | ] TRACE UNICAST3 - NODE_2 <-- DATA(NODE_2: #64, conn_id=1) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.302 [jgrp-174 | ] TRACE UNICAST3 - NODE_2: delivering NODE_2#64 | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.302 [jgrp-174 | ] TRACE GMS - NODE_2: got merge request from NODE_2, merge_id=NODE_2::22, mbrs=[NODE_2] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.303 [jgrp-174 | ] TRACE UNICAST3 - NODE_2 --> DATA(NODE_2: #65, conn_id=1) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.303 [jgrp-174 | ] TRACE TCP - NODE_2: sending msg to NODE_2, src=NODE_2, headers are GMS: GmsHeader[MERGE_RSP]merge_id=NODE_2::22, UNICAST3: DATA, seqno=65, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.303 [jgrp-174 | ] TRACE TCP - NODE_2: looping back message [dst: NODE_2, src: NODE_2 (3 headers), size=51 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[MERGE_RSP]merge_id=NODE_2::22, UNICAST3: DATA, seqno=65, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.304 [jgrp-179 | ] TRACE UNICAST3 - NODE_2: delivering #65 - #65 (1 messages) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.304 [jgrp-179 | ] TRACE GMS - NODE_2: got merge response from NODE_2, merge_id=NODE_2::22, merge data is sender=NODE_2, view=[NODE_2|24] (1) [NODE_2], digest=NODE_2: [21 (21)] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.304 [jgrp-177 | ] TRACE TCP - NODE_2: received [dst: NODE_2, src: NODE_2 (3 headers), size=51 bytes, flags=OOB|INTERNAL, transient_flags=OOB_DELIVERED], headers are GMS: GmsHeader[MERGE_RSP]merge_id=NODE_2::22, UNICAST3: DATA, seqno=65, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.304 [jgrp-177 | ] TRACE UNICAST3 - NODE_2 <-- DATA(NODE_2: #65, conn_id=1) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.305 [jgrp-177 | ] TRACE TCP - NODE_2: received [dst: NODE_2, src: NODE_1 (flags=1) (3 headers), size=53 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[MERGE_RSP]merge_id=NODE_2::22, UNICAST3: DATA, seqno=19751, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.305 [jgrp-177 | ] TRACE UNICAST3 - NODE_2 <-- DATA(NODE_1 (flags=1): #19751, conn_id=0) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.305 [jgrp-177 | ] TRACE UNICAST3 - NODE_2: delivering NODE_1 (flags=1)#19751 | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.306 [jgrp-177 | ] TRACE GMS - NODE_2: got merge response from NODE_1 (flags=1), merge_id=NODE_2::22, merge data is sender=NODE_1 (flags=1), view=[NODE_1 (flags=1)|3] (1) [NODE_1 (flags=1)], digest=NODE_1 (flags=1): [3 (3)] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.306 [MergeTas | ] TRACE GMS - NODE_2: collected 2 merge response(s) in 6 ms | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.307 [MergeTas | ] TRACE GMS - NODE_2: consolidated view=MergeView::[NODE_1 (flags=1)|25] (2) [NODE_1 (flags=1), NODE_2], 2 subgroups: [NODE_1 (flags=1)|3] (2) [NODE_1 (flags=1), NODE_2], MergeView::[NODE_2|24] (1) [NODE_2], 1 subgroups: [NODE_2|23] (1) [NODE_2] consolidated digest=NODE_1 (flags=1): [3 (3)], NODE_2: [21 (21)] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.307 [MergeTas | ] DEBUG GMS - NODE_2: installing merge view [NODE_1 (flags=1)|25] (2 members) in 2 coords | (Log4J2LogImpl.java:71) 2019-01-17 10:11:37.307 [MergeTas | ] TRACE UNICAST3 - NODE_2 --> DATA(NODE_1 (flags=1): #33, conn_id=0) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.307 [MergeTas | ] TRACE TCP - NODE_2: sending msg to NODE_1 (flags=1), src=NODE_2, headers are GMS: GmsHeader[INSTALL_MERGE_VIEW], UNICAST3: DATA, seqno=33, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.307 [MergeTas | ] TRACE UNICAST3 - NODE_2 --> DATA(NODE_2: #66, conn_id=1) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.307 [MergeTas | ] TRACE TCP - NODE_2: sending msg to NODE_2, src=NODE_2, headers are GMS: GmsHeader[INSTALL_MERGE_VIEW], UNICAST3: DATA, seqno=66, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.308 [MergeTas | ] TRACE TCP - NODE_2: looping back message [dst: NODE_2, src: NODE_2 (3 headers), size=108 bytes], headers are GMS: GmsHeader[INSTALL_MERGE_VIEW], UNICAST3: DATA, seqno=66, conn_id=1, TP: [cluster_name=CLUSTER] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.308 [MergeTas | ] DEBUG GMS - NODE_2: merge NODE_2::22 took 9 ms | (Log4J2LogImpl.java:71) 2019-01-17 10:11:37.309 [jgrp-179 | ] TRACE TCP - NODE_2: received message batch of 1 messages from NODE_2 | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.309 [jgrp-179 | ] TRACE UNICAST3 - NODE_2 <-- DATA(NODE_2: #66 - #66) | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.309 [jgrp-179 | ] TRACE UNICAST3 - NODE_2: delivering #66 - #66 (1 messages) | (Log4J2LogImpl.java:46) 2019-01-17 10:11:37.310 [jgrp-179 | ] TRACE GMS - NODE_2: mcasting view MergeView::[NODE_1 (flags=1)|25] (2) [NODE_1 (flags=1), NODE_2], 2 subgroups: [NODE_1 (flags=1)|3] (2) [NODE_1 (flags=1), NODE_2], [NODE_2|24] (1) [NODE_2] | (Log4J2LogImpl.java:56) 2019-01-17 10:11:37.310 [jgrp-179 | ] DEBUG NAKACK2 - [NODE_2 mergeDigest()] existing digest: NODE_2: [21 (21)] new digest: NODE_1 (flags=1): [3 (3)], NODE_2: [21 (21)] resulting digest: NODE_1 (flags=1): [3 (3)], NODE_2: [21 (21)] | (Log4J2LogImpl.java:66) 2019-01-17 10:11:37.310 [jgrp-179 | ] DEBUG GMS - NODE_2: installing view MergeView::[NODE_1 (flags=1)|25] (2) [NODE_1 (flags=1), NODE_2], 2 subgroups: [NODE_1 (flags=1)|3] (2) [NODE_1 (flags=1), NODE_2], [NODE_2|24] (1) [NODE_2] | (Log4J2LogImpl.java:71)After this everything is working fine again until one node is restarted or something. I'm really clueless here and need some help. Does anyone has any idea why the NODE_1 isn't starting the join / merge earlier? Thanks for any help.
Note: I've also attached both log files.
Last edit: Jürgen Westerkamp 2019-01-18
Hi,
it turned out that the problem was the UNICAST3 protocol. The protocol tries to re-send every message to a reconnected cluster member before they are actually allowed to be merged as member into the cluster. This was the reason for all the SEQNO messages between the nodes. After we removed the protocol from the stack it works fine because in our application we don't need this feature.
I doubt this is the root cause; killing a node and restarting it has worked for decade(s)... If you come up with a reproducer (including code, configuration and instructions to reproduce), I'll take a look.
Note that if you remove UNICAST3, you will destroy ordering guaranteesfor unicast messages.
[1] http://www.jgroups.org/manual4/index.html#UNICAST3