[jboss-user] [JBoss Remoting Users] - Re: No ping on secondaryBindPort
enriqueam
do-not-reply at jboss.com
Wed Sep 30 11:24:21 EDT 2009
Just to give a bit of more information, once the port TCP 4458 times out at the firewall and a new message comes in, this is what we get in the trace file
| 762021 [Timer-1] TRACE org.jboss.remoting.MicroRemoteClientInvoker - SocketClientInvoker[a89ce3, bisocket://192.168.6.1:4457] received InvocationResponse so going to return response's return value of true
|
| 762021 [Timer-1] TRACE org.jboss.remoting.ConnectionValidator - ConnectionValidator got successful ping using SocketClientInvoker[a89ce3, bisocket://192.168.6.1:4457]
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - read version 22 from input stream
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - blocking to read invocation from unmarshaller
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Reading
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Stream is already DataInputStream :)
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Created packet ClientDelivery[null]
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Reading packet
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Read packet
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Returning payload: InvocationRequest[127a20c, CALLBACK, OnewayInvocation[InternalInvocation[fff2a2]]]
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - read InvocationRequest[127a20c, CALLBACK, OnewayInvocation[InternalInvocation[fff2a2]]] from unmarshaller
| 770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - about to call SocketServerInvoker[UNINITIALIZED].invoke()
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] received OnewayInvocation[InternalInvocation[fff2a2]]
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - reusing oneway thread pool
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] placing InvocationRequest[127a20c, CALLBACK, InternalInvocation[fff2a2]] in onewayThreadPool
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] received InternalInvocation[fff2a2]
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - handling InternalInvocation where method name = handleCallback
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - ServerInvoker (SocketServerInvoker[UNINITIALIZED]) is being asked to deliver callback on client callback handler with session id of null.
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] successfully dispatched invocation, returning null from subsystem 'CALLBACK' to client null
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - SocketServerInvoker[UNINITIALIZED].invoke() returned null
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - oneway request, writing no reply on the wire
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - preparing to process next invocation invocation
| 770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - blocking to read version from input stream
| 770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - org.jboss.jms.client.container.ClientConsumer$HandleMessageRunnable at 1927ba1 receiving message delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2 from the remoting layer
| 770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - org.jboss.jms.client.container.ClientConsumer$HandleMessageRunnable at 1927ba1 added message(s) to the buffer are now 1 messages
| 770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Receiver thread:null listener:EventHandler at 8ae45a listenerRunning:false sessionExecutor:org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor at 19646fd
| 770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - ClientConsumer[8-21b4780g-1-0fi3780g-82997k-110j3] scheduled a new ListenerRunner
| 770832 [Thread-8] TRACE org.jboss.jms.client.container.SessionAspect - SessionAspect[1b48392] added Delivery[2, delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2] to session state
| 770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - calling listener's onMessage(delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2)
|
| OUR EventHandler.OnMessage() is called
|
| 770834 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - SocketException received. This is likely due to client disconnecting and resetting connection.
| java.net.SocketException: Connection reset
| at java.net.SocketInputStream.read(SocketInputStream.java:168)
| at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
| at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
| at java.io.FilterInputStream.read(FilterInputStream.java:66)
| at org.jboss.remoting.transport.socket.ServerThread.readVersion(ServerThread.java:879)
| at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:546)
| at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:421)
| at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:174)
|
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - listener's onMessage() finished
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Calling postDeliver
| 770834 [WorkerThread#0[192.168.6.1:4458]] DEBUG org.jboss.remoting.transport.socket.ServerThread - WorkerThread#0[192.168.6.1:4458] closing socketWrapper: ServerSocketWrapper[Socket[addr=/192.168.6.1,port=4458,localport=41721].14a9387]
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.SessionAspect - SessionAspect[1b48392] auto acknowledging delivery Delivery[2, delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2]
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Called postDeliver
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Called callonMessage
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - no more messages in buffer, marking listener as not running
| 770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Exiting run()
| 770835 [WorkerThread#0[192.168.6.1:4458]] DEBUG org.jboss.jms.server.remoting.ServerSocketWrapper - cannot write CLOSING byte
| java.net.SocketException: Broken pipe
| at java.net.SocketOutputStream.socketWrite0(Native Method)
| at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
| at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
| at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
| at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
| at java.io.DataOutputStream.flush(DataOutputStream.java:106)
| at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
| at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:521)
| at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:174)
| 770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.SocketWrapper - ServerSocketWrapper[Socket[addr=/192.168.6.1,port=4458,localport=41721].14a9387] closing socket
| 770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.SocketWrapper - ServerSocketWrapper[Socket[addr=/192.168.6.1,port=4458,localport=41721].14a9387] closed socket
| 770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - WorkerThread#0[192.168.6.1:4458] removing itself from clientpool and going to threadpool
| 770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - WorkerThread#0[192.168.6.1:4458] begins to wait
| 771992 [Timer-0] TRACE org.jboss.remoting.LeasePinger - LeasePinger[5c4o62-sgual5-g08745nr-1-g08746fe-7:SocketClientInvoker[1dc0e7a, bisocket://192.168.6.1:4457](5c4o62-sgual5-g08745nr-1-g08746f9-6)] sending ping to server. Currently managing lease for following clients:
| 5c4o62-sgual5-g08745nr-1-g08746ey-4
|
| 771992 [Timer-0] TRACE org.jboss.remoting.MicroRemoteClientInvoker - SocketClientInvoker[1dc0e7a, bisocket://192.168.6.1:4457](1) invoking InvocationRequest[1f4e1c6, $PING$]
|
So after the problem is detected in ServerThread and SocketWrapper has closed the socket, I can see that the ServerThread removes itself from the client pool, notifies it and then it waits (as shown in the last bold line in the trace). What it seems is that ServerThread is never notified because I NEVER get the trace
| WorkerThread#0[192.168.6.1:4458] woke up after wait
|
as specified in the source code:
| while (true)
| {
| try
| {
| if(trace) { log.trace(this + " begins to wait"); }
|
| wait();
|
| if(trace) { log.trace(this + " woke up after wait"); }
|
| break;
| }
| catch (InterruptedException e)
| {
| if (shutdown)
| {
| invoker = null;
| return; // exit thread
| }
| }
| }
|
Hope it helps.
View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4257886#4257886
Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4257886
More information about the jboss-user
mailing list