10:24 a.m.
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@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@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@8ae45a listenerRunning:false
sessionExecutor:org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor@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#...
Reply to the post :
http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&a...
5568
days inactive
5568
days old
0 comments
1 participants
participants (1)
-
enriqueam