[JBoss-dev] [ jboss-Bugs-808170 ] Partition problems 3.2.2RC4

[SourceForge.net <no...@so...>]

Bugs item #808170, was opened at 2003-09-17 21:19
Message generated for change (Comment added) made by ejort
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=376685&aid=808170&group_id=22866

Category: Clustering
Group: v3.2
Status: Open
Resolution: None
Priority: 5
Submitted By: Adrian Brock (ejort)
Assigned to: Bela Ban (belaban)
Summary: Partition problems 3.2.2RC4

Initial Comment:
JBoss-3.2.2RC4 (current CVS)

Java1.4.2

Redhat 9



I'm seeing problems with nodes in a partition discovering

each other.



Sometimes it works,



Sometimes is doesn't (see attached console.log and

console2.log)

I have cluster logs as well if you need them.

Shutdown blocks on the partition when it fails 

(see threaddumps at end of logs)



Sometimes I get a NullPointerException

03-09-17 19:07:32,545 DEBUG

[org.jboss.ha.framework.interfaces.HAPartition.Def

aultPartition] Get current members

2003-09-17 19:07:32,546 INFO 

[org.jboss.ha.framework.interfaces.HAPartition.Def

aultPartition] Number of cluster members: 2

2003-09-17 19:07:32,556 INFO 

[org.jboss.ha.framework.interfaces.HAPartition.Def

aultPartition] Other members: 1

2003-09-17 19:07:32,566 WARN 

[org.jboss.ha.framework.interfaces.HAPartition.Def

aultPartition] No additional information has been found

in the JavaGroup

address

: make sure you are running with a correct version of

JavaGroups and

that the pr

otocol  you are using supports the 'additionalData'

behaviour

2003-09-17 19:07:32,577 ERROR

[org.jboss.ha.framework.server.ClusterPartition] S

tarting failed

java.lang.NullPointerException

        at

org.jboss.ha.framework.server.HAPartitionImpl.verifyNodeIsUnique(HAPa

rtitionImpl.java:763)

        at

org.jboss.ha.framework.server.HAPartitionImpl.startPartition(HAPartit

ionImpl.java:236)

        at

org.jboss.ha.framework.server.ClusterPartition.startService(ClusterPa

rtition.java:293)

        at

org.jboss.system.ServiceMBeanSupport.start(ServiceMBeanSupport.java:1

92)

        at

sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)

        at

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces



Regards,

Adrian

----------------------------------------------------------------------

>Comment By: Adrian Brock (ejort)
Date: 2003-09-23 18:04

Message:
Logged In: YES 
user_id=9459

Correction is does reach UDP. 



Regards,

Adrian

----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-23 17:59

Message:
Logged In: YES 
user_id=9459

I've librarly added System.out.printlns to the jgroups source.

Attaced is test.txt from a run where one works and the other

does not.

I don't see the Config event reaching UDP when it fails,

it doesn't invoke setAdditionalData.



Regards,

Adrian

----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-23 16:50

Message:
Logged In: YES 
user_id=9459

Yes, you have to make the same change to AddDataTest.java



Regards,

Adrian

----------------------------------------------------------------------

Comment By: Sacha Labourey (slaboure)
Date: 2003-09-23 16:46

Message:
Logged In: YES 
user_id=95900

Hello Adrian,



What do you mean by "You have to swap the pbcast 

elements "? To make jboss start I had to swap STABLE and 

NAKACK otherwise I get an ordering exception from JG.

----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-23 16:42

Message:
Logged In: YES 
user_id=9459

Sacha has upgraded to jgroups but I'm still seeing the problem.



Tested with JBoss but also see the problem with the attached

test.

You have to swap the pbcast elements in the attached test

to make it run.



Did Sacha get the correct version?

Do you need anything from me to debug it?



Regards,

Adrian

----------------------------------------------------------------------

Comment By: Bela Ban (belaban)
Date: 2003-09-23 00:46

Message:
Logged In: YES 
user_id=34890

I fixed this in JGroups CVS head. I can backport it to any

JavaGroups version if you want me to.



Otherwise, the change is in ProtocolStack.start() and Queue.



Sacha, Adrian ?

----------------------------------------------------------------------

Comment By: Bela Ban (belaban)
Date: 2003-09-22 18:25

Message:
Logged In: YES 
user_id=34890

I know what the problem is, working on a solution.



A simple quick fix is to add a timeout (say 500ms) after

sending down the CONFIG event, and before connecting.



Bela

----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-22 13:31

Message:
Logged In: YES 
user_id=9459

It is definitly a race condition.

I add some System.out.printlns to the javagroups source

(the jboss tagged version).

I even got it to fail with the default configuration



<DefaultConfiguration>



checking for additional data Thread[main,5,main]

handling config event {additional_data=[B@df503}

Thread[DownHandler (UDP),5,main]



-------------------------------------------------------

GMS: address is htimes2:34016

-------------------------------------------------------

address is htimes2:34016





<JBossConfiguration>



UDP(mcast_addr=228.1.2.3;mcast_port=45566;ip_ttl=64;ip_mcast=true;mcast_send_buf_size=150000;mcast_recv_buf_size=80000;ucast_send_buf_size=150000;ucast_recv_buf_size=80000;loopback=false):PING(timeout=2000;num_initial_members=3;up_thread=true;down_thread=true):MERGE2(min_interval=5000;max_interval=10000):FD(shun=true;up_thread=true;down_thread=true;timeout=2500;max_tries=5):VERIFY_SUSPECT(timeout=3000;num_msgs=3;up_thread=true;down_thread=true):pbcast.STABLE(desired_avg_gossip=20000;up_thread=true;down_thread=true):pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;up_thread=true;down_thread=true):UNICAST(timeout=5000;window_size=100;min_threshold=10;down_thread=true):FRAG(frag_size=8192;down_thread=true;up_thread=true):pbcast.GMS(join_timeout=5000;join_retry_timeout=2000;shun=true;print_local_addr=true):pbcast.STATE_TRANSFER(up_thread=true;down_thread=true)

checking for additional data Thread[main,5,main]



-------------------------------------------------------

GMS: address is htimes2:34018

-------------------------------------------------------

handling config event {additional_data=[B@998b08}

Thread[DownHandler (UDP),5,main]

address is htimes2:34018



----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-22 13:01

Message:
Logged In: YES 
user_id=9459

Hi Bela,



Your test works for me, however using the JBoss protocol stack

it fails. See attached test.



Regards,

Adrian

----------------------------------------------------------------------

Comment By: Sacha Labourey (slaboure)
Date: 2003-09-19 06:28

Message:
Logged In: YES 
user_id=95900

Hello Bela,



No, I don't agree, take a look at the code starting at 

ClusterPartition.startService() i.e. line 282:



	java.util.HashMap staticNodeName = new 

java.util.HashMap();

	staticNodeName.put("additional_data", 

this.nodeName.getBytes());

	this.channel.down (new Event(Event.CONFIG, 

staticNodeName));

	

	channel.connect(partitionName);



This is exactly what you do in your sample code. Would it be 

possible that you have a race condition and that the connect 

occurs while the channel.down call is not yet finished? Is it 

handle by a single thread (the calling thread) or is it 

asynchronous?



It seems that the this.channel.down call does NOT SEND the 

event down the stack but INSTEAD queue it and waits for the 

channel.connect call.



Bela, do you queue your Events waiting for the 

channel.connect call or do you process them asynchronously?

----------------------------------------------------------------------

Comment By: Bela Ban (belaban)
Date: 2003-09-18 22:35

Message:
Logged In: YES 
user_id=34890

Wait, Sacha,



the cluster.log shows clearly that you connect to the

channel *first*, the send down the CONFIG event. This is

incorrect.



Bela

----------------------------------------------------------------------

Comment By: Bela Ban (belaban)
Date: 2003-09-18 22:25

Message:
Logged In: YES 
user_id=34890

Sacha,



are you passing a Map as arg of the CONFIG event ? Also, the

key has to be "additional_data", e.g. as used in the code

below (you can set a breakpoint here to see what's going on):



in UDP.handleDownEvent():



   void handleConfigEvent(HashMap map) {

        if(map == null) return;

        if(map.containsKey("additional_data"))

            additional_data=(byte[])map.get("additional_data");

        if(map.containsKey("send_buf_size")) {

           

mcast_send_buf_size=((Integer)map.get("send_buf_size")).intValue();

            ucast_send_buf_size=mcast_send_buf_size;

        }

        if(map.containsKey("recv_buf_size")) {

           

mcast_recv_buf_size=((Integer)map.get("recv_buf_size")).intValue();

            ucast_recv_buf_size=mcast_recv_buf_size;

        }

        setBufferSizes();

    }



The second thing is that when the member is starting, you

should see the address *with* additional data, ie, the

program below prints the output:





public class AddDataTest {



    public static void main(String[] args) {

        try {

            JChannel c=new JChannel();

            Map m=new HashMap();

            m.put("additional_data", "Node #1".getBytes());

            c.down(new Event(Event.CONFIG, m));

            c.connect("bla");

            System.out.println("address is " +

c.getLocalAddress());

        }

        catch(ChannelException e) {

            e.printStackTrace();

        }

    }



}





-------------------------------------------------------

GMS: address is lotusman:50416 (additional data: 7 bytes)

-------------------------------------------------------

address is lotusman:50416 (additional data: 7 bytes)







----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-18 15:04

Message:
Logged In: YES 
user_id=9459

I still get failures without the default gateway configured.



Attached netstat -an > netstat.txt

----------------------------------------------------------------------

Comment By: Sacha Labourey (slaboure)
Date: 2003-09-18 08:27

Message:
Logged In: YES 
user_id=95900

That is really strange. Bela, any idea on what is happening? 

The thing is that:

 - I create the JChannel

 - send a config event down the stack THAT CONTAINS 

additional data

 - connect the JChannel

 - ask the JChannel for my node name and the view



and my node name does NOT contain the additional data!?!



Here is the excerpt from the log that shows that:



2003-09-17 21:59:33,277 INFO  

[org.jboss.ha.framework.server.ClusterPartition] Starting





=> SL: Here, I've build my "additional data" using some 

information from the currently running server, we have no 

exception and nothing logged, so everything went fine in 

ClusterPartition.generateUniqueNodeName()



=> SL: next cal is JChannel.connect():





2003-09-17 21:59:33,288 DEBUG 

[org.jboss.ha.framework.server.ClusterPartition] Starting 

ClusterPartition: DefaultPartition

2003-09-17 21:59:33,294 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] UDP.start(): creating sockets and starting 

threads

2003-09-17 21:59:33,296 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] UDP.createSockets(): unicast sockets will use 

interface 192.168.0.51

2003-09-17 21:59:33,305 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] UDP.createSockets(): socket information:

local_addr=htimes2:34107, mcast_addr=228.1.2.3:45566, 

bind_addr=/192.168.0.51, ttl=64

send socket: bound to 192.168.0.51:34106, send buffer 

size=65535

receive socket: bound to 192.168.0.51:34107, receive buffer 

size=65535

multicast socket: bound to 192.168.0.51:45566, send buffer 

size=65535, receive buffer size=65535

2003-09-17 21:59:33,312 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] UDP.startThreads(): created unicast receiver 

thread

2003-09-17 21:59:33,431 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] FRAG.down(): received CONFIG event: 

{additional_data=[B@f62eba}

2003-09-17 21:59:33,432 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] NAKACK.down(): received CONFIG event: 

{additional_data=[B@f62eba}

2003-09-17 21:59:33,434 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] UDP.down(): received CONFIG event: 

{additional_data=[B@f62eba}





=> SL: Here we can see that the UDP layer (above) has some 

additional_data received by the CONFIG event: [B@f62eba





2003-09-17 21:59:33,445 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:33 BST 

2003] [INFO] PING.down(): FIND_INITIAL_MBRS

2003-09-17 21:59:35,459 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] PING.down(): initial mbrs are []

2003-09-17 21:59:35,461 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [DEBUG] ClientGmsImpl.join(): initial_mbrs are []

2003-09-17 21:59:35,461 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] ClientGmsImpl.join(): no initial members 

discovered: creating group as first member

2003-09-17 21:59:35,463 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] GMS.installView(): view is [htimes2:34107|0] 

[htimes2:34107]

2003-09-17 21:59:35,479 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] GMS.setImpl(): changed role to 

org.javagroups.protocols.pbcast.CoordGmsImpl

2003-09-17 21:59:35,479 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] GMS.becomeCoordinator(): htimes2:34107 

became coordinator

2003-09-17 21:59:35,480 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] ClientGmsImpl.becomeSingletonMember(): 

created group (first member). My view is [htimes2:34107|0], 

impl is org.javagroups.protocols.pbcast.CoordGmsImpl

2003-09-17 21:59:35,605 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] STABLE.startStableTask(): stable task started; 

num_gossip_runs=3, max_gossip_runs=3

2003-09-17 21:59:35,627 TRACE 

[org.javagroups.DefaultPartition] [Wed Sep 17 21:59:35 BST 

2003] [INFO] MERGE2.FindSubgroups.run(): merge task started

2003-09-17 21:59:35,834 DEBUG 

[org.jboss.ha.framework.interfaces.HAPartition.DefaultPartition

] ViewAccepted: initial members set

2003-09-17 21:59:35,835 INFO  

[org.jboss.ha.framework.server.ClusterPartition] Starting 

channel



=> SL: at this point, the call to JChannel.connect() is finished 

and we start the HAPartition which will call 

JChannel.getLocalAddress() and the recieved JG IPAddress 

object does NOT contain the additional_data: WHY?





2003-09-17 21:59:35,836 DEBUG 

[org.jboss.ha.framework.interfaces.HAPartition.DefaultPartition

] get nodeName

2003-09-17 21:59:35,836 DEBUG 

[org.jboss.ha.framework.interfaces.HAPartition.DefaultPartition

] Get current members

2003-09-17 21:59:35,837 INFO  

[org.jboss.ha.framework.interfaces.HAPartition.DefaultPartition

] Number of cluster members: 1

2003-09-17 21:59:35,837 INFO  

[org.jboss.ha.framework.interfaces.HAPartition.DefaultPartition

] Other members: 0

2003-09-17 21:59:35,837 WARN  

[org.jboss.ha.framework.interfaces.HAPartition.DefaultPartition

] No additional information has been found in the JavaGroup 

address: make sure you are running with a correct version of 

JavaGroups and that the protocol  you are using supports 

the 'additionalData' behaviour





Any idea Bela?

----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-17 23:51

Message:
Logged In: YES 
user_id=9459

cat /etc/hosts

# Do not remove the following line, or various programs

# that require network functionality will fail.

192.168.0.51    htimes2

127.0.0.1       localhost.localdomain   localhost

127.0.0.1       4pcvs



There are no other instances of jboss on the network.

Sorry can't provide netstat, I'm no longer running the

configuration.



One thing occurs to me (I'm configured with a default gateway)

maybe the gateway is interfering with udp? I'll try it again

without the default gateway setting.



Regards,

Adrian

----------------------------------------------------------------------

Comment By: Scott M Stark (starksm)
Date: 2003-09-17 23:37

Message:
Logged In: YES 
user_id=175228

I have an RH9 system with JDK 1.4.2 that I have tried this

recepie on a few times and don't see the problem. One issue

with the "...  'additionalData'' warning is that if this

occurs you are guarenteed to see an NPE so we should just be

throwing an exception rather than logging a msg and then

proceeding to an NPE.



Do you have another cluster running somewhere else? I'll

have to look into the logs.



----------------------------------------------------------------------

Comment By: Adrian Brock (ejort)
Date: 2003-09-17 21:23

Message:
Logged In: YES 
user_id=9459

To construct my two nodes:



cp -r all all2

edit all/conf/jboss-service.xml (uncomment service-binding)

./run.sh -c all and ./run.sh -c all2



Regards,

Adrian

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=376685&aid=808170&group_id=22866