Print

[djroze]

Hi there,

   I have been experimenting with JPPF and found it has many great features, thank you for your work on this technology! I am trying to set up a peer-to-peer server configuration where both servers (A and B) will accept regular and secure connections and where server B connects to server A over SSL (acts as a node for server A).

   Server A comes up fine and handles work/traffic with nodes over both regular and SSL connections. However, when server B is started and connects to server A there is a NullPointerException in server B's log as follows:

[DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from SENDING_PEER_CHANNEL_IDENTIFIER to SENDING_PEER_INITIATION_REQUEST with ops=5 for channel SelectionKeyWrapper[id=1, <A_ADDRESS>:<A_SSL_PORT>, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=1], state=SENDING_PEER_CHANNEL_IDENTIFIER, resource=null, pendingResponses=0, type=node, peer=true, uuid=null]
[DEBUG][org.jppf.server.peer.PeerNode.run(125)]: Connection reset
java.net.SocketException: Connection reset
        at java.net.SocketInputStream.read(SocketInputStream.java:189)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:312)
        at sun.security.ssl.InputRecord.read(InputRecord.java:350)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1328)
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:882)
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
        at java.io.DataInputStream.readInt(DataInputStream.java:387)
        at org.jppf.comm.socket.AbstractSocketWrapper.readInt(AbstractSocketWrapper.java:264)
        at org.jppf.io.SocketWrapperInputSource.readInt(SocketWrapperInputSource.java:90)
        at org.jppf.io.IOHelper.readData(IOHelper.java:120)
        at org.jppf.io.IOHelper.unwrappedData(IOHelper.java:186)
        at org.jppf.server.peer.PeerNode.readBundle(PeerNode.java:214)
        at org.jppf.server.peer.PeerNode.perform(PeerNode.java:159)
        at org.jppf.server.peer.PeerNode.run(PeerNode.java:121)
        at org.jppf.server.peer.JPPFPeerInitializer.run(JPPFPeerInitializer.java:84)
[ERROR][org.jppf.server.peer.JPPFPeerInitializer.run(88)]:
java.lang.NullPointerException
        at org.jppf.server.peer.PeerNode.getName(PeerNode.java:267)
        at org.jppf.server.peer.PeerNode.run(PeerNode.java:104)
        at org.jppf.server.peer.JPPFPeerInitializer.run(JPPFPeerInitializer.java:84)
[INFO ][org.jppf.server.peer.JPPFPeerInitializer.run(92)]: end initialization of peer [A]

The portions of the configs I believe to be relevant are as follows:

Server A:
jppf.server.host = <A_ADDRESS>
jppf.server.port = <A_PORT>
jppf.ssl.server.port = <A_SSL_PORT>
jppf.ssl.configuration.file = config/ssl/A.properties
jppf.management.enabled = true
jppf.management.port = <A_JMX_PORT>
jppf.management.ssl.enabled = true
jppf.management.ssl.port = <A_SSL_JMX_PORT>
jppf.peer.ssl.enabled = true
jppf.recovery.enabled = false

Server B:
jppf.server.host = <B_ADDRESS>
jppf.server.port = <B_PORT>
jppf.ssl.server.port = <B_SSL_PORT>
jppf.ssl.configuration.file = config/ssl/B.properties
jppf.management.enabled = true
jppf.management.port = <B_JMX_PORT>
jppf.management.ssl.enabled = true
jppf.management.ssl.port = <B_SSL_JMX_PORT>
jppf.peer.ssl.enabled = true
jppf.peers = A
jppf.peer.A.server.host = <A_ADDRESS>
jppf.peer.A.server.port = <A_SSL_PORT>
jppf.recovery.enabled = false

   I am using version 3.3.6 of all components. I believe sometimes this error *doesn't* happen on startup and instead another one does, but I'm hoping we can troubleshoot this first and then see what else may be wrong. Please let me know if you can provide any guidance for why this is happening and if I can provide any other useful info. Thanks in advance!

- Daniel

[djroze]

Also, I forgot to mention, server B is on a different subnet than server A, which it seems should be possible given that one of the architecture diagrams on this site shows peer-to-peer server connections crossing network boundaries.

[lolo]

Hello Daniel,

First off, I'm assuming the NPE is caused by the SocketException that happens just before, even though it's difficult to say how long before it happened, since the log doesn't show timestamps.
Normally, "Connection reset" means the connection was terminated by the remote peer, so it would be very interesting to see what can be found in the log of server A. Can you see any exception there?

Also, I confirm that the connection will work even if A and B are on different networks, provided you do not rely on discovery (I see that indeed you configured it manually), since discovery is based on UDP multicast.

Sincerely,
-Laurent

[djroze]

Hi Laurent,

   Thanks for the quick reply. Sorry for the omission of the timestamps, I thought that might make it easier to read but apparently left out some important information. Here are the portions of both A and B's logs that appear during the initial peer-to-peer connection process:

Server A:

2013-11-13 19:17:57,048 [DEBUG][org.jppf.server.nio.PlainNioObject.read(96)]: read 4 bytes from input source, count/size = 4/4
2013-11-13 19:17:57,049 [DEBUG][org.jppf.server.nio.PlainNioObject.read(99)]: count = 4, size = 4
2013-11-13 19:17:57,069 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(73)]: read identifier 'NODE_CLASSLOADER_CHANNEL' for SelectionKeyWrapper[id=3, <B_HOSTNAME>:38949, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=3], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:17:57,069 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(92)]: cancelling key for SelectionKeyWrapper[id=3, <B_HOSTNAME>:38949, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=3], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:17:57,070 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(96)]: registering channel with new server Thread[NodeClassServer,5,main]
2013-11-13 19:17:57,173 [DEBUG][org.jppf.server.nio.PlainNioObject.read(96)]: read 4 bytes from input source, count/size = 4/4
2013-11-13 19:17:57,175 [DEBUG][org.jppf.server.nio.PlainNioObject.read(99)]: count = 4, size = 4
2013-11-13 19:17:57,181 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(73)]: read identifier 'NODE_JOB_DATA_CHANNEL' for SelectionKeyWrapper[id=5, <B_HOSTNAME>:38950, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=5], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:17:57,182 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(92)]: cancelling key for SelectionKeyWrapper[id=5, <B_HOSTNAME>:38950, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=5], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:17:57,182 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(96)]: registering channel with new server Thread[NodeJobServer,5,main]
2013-11-13 19:17:57,394 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 19:17:57,397 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 19:17:57,402 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(102)]: channel registered: SelectionKeyWrapper[id=6, <B_HOSTNAME>:38950, readyOps=0, keyOps=5, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=6], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:17:57,404 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(102)]: channel registered: SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=0, keyOps=1, context=channel=SelectionKeyWrapper[id=4], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=false, uuid=null]
2013-11-13 19:17:57,417 [DEBUG][org.jppf.server.nio.StateTransitionTask.run(92)]: error on channel SelectionKeyWrapper[id=6, <B_HOSTNAME>:38950, readyOps=5, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=6], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]] : java.net.ConnectException: node SelectionKeyWrapper[id=6, <B_HOSTNAME>:38950, readyOps=5, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=6], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]] has been disconnected
java.net.ConnectException: node SelectionKeyWrapper[id=6, <B_HOSTNAME>:38950, readyOps=5, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=6], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]] has been disconnected
        at org.jppf.server.nio.nodeserver.SendInitialBundleState.performTransition(SendInitialBundleState.java:63)
        at org.jppf.server.nio.nodeserver.SendInitialBundleState.performTransition(SendInitialBundleState.java:32)
        at org.jppf.server.nio.StateTransitionTask.run(StateTransitionTask.java:82)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:724)
2013-11-13 19:17:57,940 [DEBUG][org.jppf.server.nio.classloader.node.WaitingInitialNodeRequestState.performTransition(73)]: read initial request from node SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=false, uuid=null]
2013-11-13 19:17:57,949 [DEBUG][org.jppf.server.nio.classloader.node.WaitingInitialNodeRequestState.performTransition(76)]: initiating node: SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=null]
2013-11-13 19:17:57,950 [DEBUG][org.jppf.server.nio.classloader.node.NodeClassNioServer.addNodeConnection(135)]: adding node connection: uuid=58B0BDF8-3DAA-1D48-995E-4BE5FD46F143, channel=SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=58B0BDF8-3DAA-1D48-995E-4BE5FD46F143]
2013-11-13 19:17:57,952 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from WAITING_INITIAL_NODE_REQUEST to SENDING_INITIAL_NODE_RESPONSE with ops=5 for channel SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=58B0BDF8-3DAA-1D48-995E-4BE5FD46F143]
2013-11-13 19:17:57,954 [DEBUG][org.jppf.server.nio.classloader.node.SendingInitialNodeResponseState.performTransition(70)]: sent uuid=8BDDA3C3-4791-6924-F95A-12C9E1C2E2A1 to node SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=SENDING_INITIAL_NODE_RESPONSE, resource=null, pendingResponses=0, type=node, peer=true, uuid=58B0BDF8-3DAA-1D48-995E-4BE5FD46F143]
2013-11-13 19:17:57,955 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from SENDING_INITIAL_NODE_RESPONSE to WAITING_NODE_REQUEST with ops=1 for channel SelectionKeyWrapper[id=4, <B_HOSTNAME>:38949, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=SENDING_INITIAL_NODE_RESPONSE, resource=null, pendingResponses=0, type=node, peer=true, uuid=58B0BDF8-3DAA-1D48-995E-4BE5FD46F143]

Server B:

2013-11-13 11:17:54,981 [DEBUG][org.jppf.server.peer.PeerResourceProvider.init(104)]: Attempting connection to remote peer [<A_ADDRESS>:<A_SSL_PORT>]
2013-11-13 11:17:54,982 [DEBUG][org.jppf.comm.socket.SocketInitializerImpl.initializeSocket(67)]: SocketInitializerImpl[<A_ADDRESS>:<A_SSL_PORT>] about to close socket wrapper
2013-11-13 11:17:55,103 [DEBUG][org.jppf.comm.socket.SocketChannelClient.open(280)]: getReceiveBufferSize() = 32768
2013-11-13 11:17:55,104 [DEBUG][org.jppf.server.peer.PeerResourceProvider.init(107)]: Connected to remote peer [<A_ADDRESS>:<A_SSL_PORT>]
2013-11-13 11:17:55,113 [DEBUG][org.jppf.server.peer.PeerResourceProvider.postInit(124)]: registered class server channel SelectionKeyWrapper[id=1, <A_ADDRESS>:<A_SSL_PORT>, readyOps=0, keyOps=0, context=channel=SelectionKeyWrapper[id=1], state=null, resource=null, pendingResponses=0, type=node, peer=true, uuid=null]
2013-11-13 11:17:55,123 [DEBUG][org.jppf.server.peer.PeerNode.run(95)]: <A>Start of peer node main loop
2013-11-13 11:17:55,123 [DEBUG][org.jppf.server.peer.RemotePeerConnection.init(83)]: <A> initializing socket client
2013-11-13 11:17:55,124 [DEBUG][org.jppf.server.peer.RemotePeerConnection.initchannel(117)]: <A>initializing socket client
2013-11-13 11:17:55,134 [DEBUG][org.jppf.server.peer.RemotePeerConnection.init(95)]: <A>@<A_ADDRESS>:<A_SSL_PORT>initializing socket
2013-11-13 11:17:55,135 [DEBUG][org.jppf.comm.socket.SocketInitializerImpl.initializeSocket(67)]: SocketInitializerImpl[<A_ADDRESS>:<A_SSL_PORT>] about to close socket wrapper
2013-11-13 11:17:55,136 [DEBUG][org.jppf.server.nio.PlainNioObject.write(120)]: wrote 4 bytes to output destination, count/size = 4/4 (dl = org.jppf.io.MultipleBuffersLocation@36efef89)
2013-11-13 11:17:55,136 [DEBUG][org.jppf.comm.socket.AbstractSocketWrapper.open(290)]: before connect()
2013-11-13 11:17:55,136 [DEBUG][org.jppf.server.nio.classloader.ClassContext.writeIdentifier(147)]: sent channel identifier NODE_CLASSLOADER_CHANNEL to peer server
2013-11-13 11:17:55,138 [DEBUG][org.jppf.server.nio.classloader.client.SendingPeerChannelIdentifierState.performTransition(78)]: sent peer channel identitifer to server SelectionKeyWrapper[id=1, <A_ADDRESS>:<A_SSL_PORT>, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=1], state=SENDING_PEER_CHANNEL_IDENTIFIER, resource=null, pendingResponses=0, type=node, peer=true, uuid=null]
2013-11-13 11:17:55,202 [DEBUG][org.jppf.comm.socket.AbstractSocketWrapper.open(292)]: after connect()
2013-11-13 11:17:55,203 [DEBUG][org.jppf.comm.socket.AbstractSocketWrapper.open(295)]: getReceiveBufferSize() = 32768
2013-11-13 11:17:55,204 [DEBUG][org.jppf.server.peer.RemotePeerConnection.init(99)]: sending channel identifier
2013-11-13 11:17:55,258 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 11:17:55,259 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 11:17:55,267 [DEBUG][org.jppf.server.peer.PeerNode.perform(156)]: <A>@<A_ADDRESS>:<A_SSL_PORT>Start of peer node secondary loop
2013-11-13 11:17:55,268 [DEBUG][org.jppf.server.peer.PeerNode.readBundle(213)]: waiting for next request
2013-11-13 11:17:55,298 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from SENDING_PEER_CHANNEL_IDENTIFIER to SENDING_PEER_INITIATION_REQUEST with ops=5 for channe
l SelectionKeyWrapper[id=1, <A_ADDRESS>:<A_SSL_PORT>, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=1], state=SENDING_PEER_CHANNEL_IDENTIFIER, resource=null, pendingResponses=0, type=node, peer=true, uuid=null]
2013-11-13 11:17:55,628 [DEBUG][org.jppf.server.peer.PeerNode.run(125)]: Connection reset
java.net.SocketException: Connection reset
        at java.net.SocketInputStream.read(SocketInputStream.java:189)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:312)
        at sun.security.ssl.InputRecord.read(InputRecord.java:350)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1328)
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:882)
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
        at java.io.DataInputStream.readInt(DataInputStream.java:387)
        at org.jppf.comm.socket.AbstractSocketWrapper.readInt(AbstractSocketWrapper.java:264)
        at org.jppf.io.SocketWrapperInputSource.readInt(SocketWrapperInputSource.java:90)
        at org.jppf.io.IOHelper.readData(IOHelper.java:120)
        at org.jppf.io.IOHelper.unwrappedData(IOHelper.java:186)
        at org.jppf.server.peer.PeerNode.readBundle(PeerNode.java:214)
        at org.jppf.server.peer.PeerNode.perform(PeerNode.java:159)
        at org.jppf.server.peer.PeerNode.run(PeerNode.java:121)
        at org.jppf.server.peer.JPPFPeerInitializer.run(JPPFPeerInitializer.java:84)
2013-11-13 11:17:55,630 [ERROR][org.jppf.server.peer.JPPFPeerInitializer.run(88)]:
java.lang.NullPointerException
        at org.jppf.server.peer.PeerNode.getName(PeerNode.java:267)
        at org.jppf.server.peer.PeerNode.run(PeerNode.java:104)
        at org.jppf.server.peer.JPPFPeerInitializer.run(JPPFPeerInitializer.java:84)
2013-11-13 11:17:55,631 [INFO ][org.jppf.server.peer.JPPFPeerInitializer.run(92)]: end initialization of peer [A]

   Probably noteworthy is that this exception only seems to occur on the first attempt of starting server B. If I start server B after a clean startup of server A, these errors appear, and then if I stop and start server B again it appears to complete peer-to-peer connection without throwing any exceptions. This is what server A's log looks like during the stop and second start of server B (the SSL exception is thrown when stopping B):

Server A (continued):

2013-11-13 19:49:35,299 [DEBUG][org.jppf.server.nio.StateTransitionTask.run(92)]: error on channel SelectionKeyWrapper[id=4, <B_HOSTNAME>:38964, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=4], state=WAITING_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=D51EECFD-D5EC-6ED1-8D73-7095B7324553] : javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
        at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
        at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1630)
        at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1598)
        at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1528)
        at org.jppf.server.nio.SSLHandler.read(SSLHandler.java:123)
        at org.jppf.server.nio.SSLNioObject.read(SSLNioObject.java:97)
        at org.jppf.server.nio.AbstractNioMessage.readNextObject(AbstractNioMessage.java:139)
        at org.jppf.server.nio.AbstractNioMessage.read(AbstractNioMessage.java:101)
        at org.jppf.server.nio.SimpleNioContext.readMessage(SimpleNioContext.java:49)
        at org.jppf.server.nio.classloader.node.WaitingNodeRequestState.performTransition(WaitingNodeRequestState.java:72)
        at org.jppf.server.nio.classloader.node.WaitingNodeRequestState.performTransition(WaitingNodeRequestState.java:37)
        at org.jppf.server.nio.StateTransitionTask.run(StateTransitionTask.java:82)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:724)
2013-11-13 19:49:35,301 [DEBUG][org.jppf.server.nio.classloader.node.NodeClassNioServer.removeNodeConnection(150)]: removing node connection: uuid=D51EECFD-D5EC-6ED1-8D73-7095B7324553
2013-11-13 19:49:43,507 [DEBUG][org.jppf.server.nio.PlainNioObject.read(96)]: read 4 bytes from input source, count/size = 4/4
2013-11-13 19:49:43,507 [DEBUG][org.jppf.server.nio.PlainNioObject.read(99)]: count = 4, size = 4
2013-11-13 19:49:43,511 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(73)]: read identifier 'NODE_CLASSLOADER_CHANNEL' for SelectionKeyWrapper[id=7, <B_HOSTNAME>:38967, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=7], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,512 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(92)]: cancelling key for SelectionKeyWrapper[id=7, <B_HOSTNAME>:38967, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=7], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,512 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(96)]: registering channel with new server Thread[NodeClassServer,5,main]
2013-11-13 19:49:43,517 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 19:49:43,518 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(102)]: channel registered: SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=0, keyOps=1, context=channel=SelectionKeyWrapper[id=8], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=false, uuid=null]
2013-11-13 19:49:43,615 [DEBUG][org.jppf.server.nio.PlainNioObject.read(96)]: read 4 bytes from input source, count/size = 4/4
2013-11-13 19:49:43,615 [DEBUG][org.jppf.server.nio.PlainNioObject.read(99)]: count = 4, size = 4
2013-11-13 19:49:43,618 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(73)]: read identifier 'NODE_JOB_DATA_CHANNEL' for SelectionKeyWrapper[id=9, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=9], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,619 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(92)]: cancelling key for SelectionKeyWrapper[id=9, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=AcceptorContext[channel=SelectionKeyWrapper[id=9], state=IDENTIFYING_PEER, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,619 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(96)]: registering channel with new server Thread[NodeJobServer,5,main]
2013-11-13 19:49:43,624 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 19:49:43,625 [DEBUG][org.jppf.server.nio.acceptor.IdentifyingPeerState.performTransition(102)]: channel registered: SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=0, keyOps=5, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,626 [DEBUG][org.jppf.server.nio.nodeserver.SendInitialBundleState.performTransition(68)]: serializing initial bundle for SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=4, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,800 [DEBUG][org.jppf.server.nio.nodeserver.SendInitialBundleState.performTransition(74)]: sent entire initial bundle for SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=4, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,807 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from SEND_INITIAL_BUNDLE to WAIT_INITIAL_BUNDLE with ops=1 for channel SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=4, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=SEND_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,881 [DEBUG][org.jppf.server.nio.classloader.node.WaitingInitialNodeRequestState.performTransition(73)]: read initial request from node SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=8], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=false, uuid=null]
2013-11-13 19:49:43,882 [DEBUG][org.jppf.server.nio.classloader.node.WaitingInitialNodeRequestState.performTransition(76)]: initiating node: SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=8], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=null]
2013-11-13 19:49:43,883 [DEBUG][org.jppf.server.nio.classloader.node.NodeClassNioServer.addNodeConnection(135)]: adding node connection: uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B, channel=SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=8], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B]
2013-11-13 19:49:43,884 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from WAITING_INITIAL_NODE_REQUEST to SENDING_INITIAL_NODE_RESPONSE with ops=5 for channel SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=1, keyOps=0, context=channel=SelectionKeyWrapper[id=8], state=WAITING_INITIAL_NODE_REQUEST, resource=null, pendingResponses=0, type=node, peer=true, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B]
2013-11-13 19:49:43,886 [DEBUG][org.jppf.server.nio.classloader.node.SendingInitialNodeResponseState.performTransition(70)]: sent uuid=55FA5AF3-8DD9-4AEA-17D9-7F74AFACC03F to node SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=8], state=SENDING_INITIAL_NODE_RESPONSE, resource=null, pendingResponses=0, type=node, peer=true, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B]
2013-11-13 19:49:43,887 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from SENDING_INITIAL_NODE_RESPONSE to WAITING_NODE_REQUEST with ops=1 for channel SelectionKeyWrapper[id=8, <B_HOSTNAME>:38967, readyOps=4, keyOps=0, context=channel=SelectionKeyWrapper[id=8], state=SENDING_INITIAL_NODE_RESPONSE, resource=null, pendingResponses=0, type=node, peer=true, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B]
2013-11-13 19:49:43,931 [DEBUG][org.jppf.server.nio.nodeserver.WaitInitialBundleState.performTransition(69)]: exec() for SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,934 [DEBUG][org.jppf.server.nio.nodeserver.WaitInitialBundleState.performTransition(69)]: exec() for SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:43,992 [DEBUG][org.jppf.server.nio.nodeserver.WaitInitialBundleState.performTransition(69)]: exec() for SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]]
2013-11-13 19:49:44,011 [DEBUG][org.jppf.server.nio.nodeserver.WaitInitialBundleState.performTransition(73)]: read bundle for SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=null, connectionUuid=null, peer=false]] done
2013-11-13 19:49:44,014 [DEBUG][org.jppf.server.nio.nodeserver.WaitInitialBundleState.performTransition(85)]: processing threads for node SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B, connectionUuid=null, peer=false]] = -1
2013-11-13 19:49:44,015 [DEBUG][org.jppf.server.nio.nodeserver.WaitInitialBundleState.performTransition(105)]: setting JPPFManagementInfo[<B_INTERNAL_ADDRESS>:<B_SSL_JMX_PORT>, type=2, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B]
2013-11-13 19:49:44,015 [DEBUG][org.jppf.server.nio.nodeserver.AbstractNodeContext.setManagementInfo(289)]: context RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B, connectionUuid=null, peer=true] setting management info [JPPFManagementInfo[<B_INTERNAL_ADDRESS>:<B_SSL_JMX_PORT>, type=2, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B]]
2013-11-13 19:49:44,019 [DEBUG][org.jppf.ssl.SSLHelper.getSSLParameters(136)]: SSL parameters : cipher suites=[SSL_RSA_WITH_RC4_128_MD5], protocols=[SSLv2Hello,SSLv3], needCLientAuth=false, wantClientAuth=false
2013-11-13 19:49:44,020 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(135)]: transition from WAIT_INITIAL_BUNDLE to IDLE with ops=0 for channel SelectionKeyWrapper[id=10, <B_HOSTNAME>:38968, readyOps=1, keyOps=0, context=RemoteNodeContext[channel=SelectionKeyWrapper[id=10], state=WAIT_INITIAL_BUNDLE, uuid=EE1C3FE8-D39A-6088-6A76-4E59FFB3286B, connectionUuid=null, peer=true]]
2013-11-13 19:49:44,021 [DEBUG][org.jppf.management.JMXConnectionThread.run(80)]: <B_INTERNAL_ADDRESS>:<B_SSL_JMX_PORT> about to perform connection attempts

   Though there is no exception thrown on the second startup, since there seem to be other issues with the P2P connection after that point I want to see if we can understand what's going on with that first exception. There is a firewall between these hosts, but I have been able to run a node (at least for a little while, the connection seems a bit unstable) from the network where B lives, so it seems like the basic paths for communication are open. Finally, it should be noted that the address that server A is trying to connect to for JMX on server B at the end (<B_INTERNAL_ADDRESS>) will not be accessible to server A, but I’m not concerned about getting monitoring working right now so hopefully that has nothing to do with the actual P2P functionality.

   Please let me know if there's any other info that can be of use, thanks so much in advance for your help!

- Daniel

[lolo]

Hi Daniel,

I have started investigating this issue and it seems there are several problems related to topologies with multiple servers in P2P. I've already identified an issue in the distributed class loader, which is a regression caused by this enhancement. I believe the issue you're facing is a different one, and I'm currently setting up an environment to try and reproduce it. I'm suspecting another regression, possibly due to the fix for JPPF-186.

I'm quite swamped today and cannot promise immediate results, but I will have an update by tomorrow. I hope this is ok.

-Laurent

[djroze]

Hi Laurent,

    Thanks very much for looking into this! No problem on the delay, just glad to hear it's not my imagination or a misuse of the system. Looking forward to hearing further updates when you get the chance, thanks again!

- Daniel

[lolo]

Hi Daniel,

For tracking purposes, I created un bug report JPPF-198 Issues with multi-server topologies. I have already fixed one of the two issues described, and I can now easily reproduce the one you are facing. I'm hoping to be able to fix it and provide a patch (for 3.3.6) by tomorrow at the latest.

Sincerely,
-Laurent

[djroze]

Hi Laurent,

   That's fantastic news, glad to hear the issue is reproducible and understood. Looking forward to the fix when you have the chance and thanks again so much!

- Daniel

[lolo]

Hi Daniel,

I have identified and fixed the remaining issue, and published a patch for it, which you can get from here: http://www.jppf.org/patch_info.php?patch_id=33

Sincerely,
-Laurent

[djroze]

Hi Laurent,

   Thanks so much! So far it looks like the new server jar is working great. The only unexpected behavior for me is that Server B appears to get sent tasks even if no active node is actually attached to it, but this isn't too surprising if Server B itself is supposed to look like a node for Server A (I can see how, depending on the algorithm for P2P server communication, Server A might not know anything about nodes actually [not] present under Server B), and I think I can work around it by just always keeping nodes running under Server B. Thanks again for the quick fix, much appreciated!

- Daniel