-
15. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Adrian,
I have attached visual vm thread monitor snap shot. if you observe, all writer tasks are in wait time since long time (attachement shows 7:51). does it mean writer tasks are never used?
-
-
16. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
leela mahesh wrote:
Adrian,
I have attached visual vm thread monitor snap shot. if you observe, all writer tasks are in wait time since long time (attachement shows 7:51). does it mean writer tasks are never used?
It looks like it to me, although I don't know the tool you are using?
The purpose of the WriteTask is to write responses asynchronously onto the socket
so it doesn't block the rest of the server while doing the I/O.
I don't see how it could be at 0.00 seconds runnable?
Even writing the pongs to the clients in response to the pings should eventually use up some cpu.
If the server is not getting the pings from the client then it should close the connections on the "read timeout".
If the client has "disappeared" then the write task will abort when it tries to write the pong
and it will then close the connection and end the threads.
Again, thread dumps are not going to tell us what is happening since they are just showing it idle.
We need to look at the logs to understand what is happening.
Without more information I can only guess, so you need to provide it.
INFO will show only FATAL errors and lifecycle messages, e.g. binding queues into jndi
DEBUG will show I/O errors and connection establishment/termination
TRACE will show everything
It's pointless continually posting the thread stuff.
-
17. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Adrian,
sorry for inconvinience. Due to some internal issues logs are not available at TRACE level. An initial analysis shows that, some point in time messages on particular queue took 3 minutes to reach from source to destination. I suspect that our application might have put huge number of messages on queue during peak hours. Is it possible that putting huge messages on queue may delay pong on the respective connection? Currently I observe this particular queue connection getting reinitialized multiple times. we have exception listener mechanism for connections.
We are planning to change server\default\deploy\jms\uil2-service.xml from default values to some other values. could you please validate is this ok?
we are running JBoss 4.2.2 on 1GB heap memory. we have around 25 queue and 25 topic connections to this JBoss. All clients and JBoss are connected by 1GB LAN.
<attribute name="PingPeriod">60000</attribute> New Value:180000
<!-- Used to disconnect the client on the serverside if there is no activity -->
<!-- Ensure this is greater than the ping period -->
<attribute name="ReadTimeout">120000</attribute> New Value:360000
<!-- Used to disconnect the client on the clientside if there is no activity -->
<!-- Ensure this is greater than the ping period -->
<attribute name="ClientReadTimeout">120000</attribute> New Value:360000
<!-- The size of the buffer (in bytes) wrapping the socket -->
<!-- The buffer is flushed after each request -->
<attribute name="BufferSize">2048</attribute> New Value:10240 -> (10KB). Assuming 50 connections 50*10=500KB
<!-- Large messages may block the ping/pong -->
<!-- A pong is simulated after each chunk (in bytes) for both reading and writing -->
<!-- It must be larger than the buffer size -->
<attribute name="ChunkSize">1000000</attribute> New Value: 100000 (100 KB)
will there be any side effects with the above configuration? will there be any issues if we receive pong before ping has been sent as I set chunk size to 100KB?
-
18. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Adrian,
Further analysis on the issue revealed that, some times connection is not getting closed from client end even after server restart with out client restart. client connection should be terminated as per time out. what could be the chance that this connection is not getting closed?
I have attached log file with TRACE level.
As per log
09:15:44,462 -org.jboss.mq.Connection Notified of failure reason=Unexpected ping failure Connection@5404683[token=ConnectionToken:Q_2_POKER_10.1.128.88_223/59280ad739196008f4ff7224868734d2 rcvstate=STOPPED]
org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)
at org.jboss.mq.Connection$PingTask.run(Connection.java:1313)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: ping timeout.
... 3 more
09:15:44,463 -JMS_LOGGER Exception on connection JMSConnection:10.1.128.85:Queue:valid:true:initializing:false:clientCount:5org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)
09:15:44,463 -JMS_LOGGER Creating connection:Queue:10.1.128.85
09:15:44,465 -JMS_LOGGER closing clients:JMSConnection:10.1.128.85:Queue:valid:true:initializing:true:clientCount:5
09:15:44,465 -JMS_LOGGER JMS: JMSMsgReceiver:close:[JMSMsgReceiver::10.1.128.85:anyRemoteGSQueue:true]
09:15:44,465 -org.jboss.mq.SpyMessageConsumer Message consumer closing. SpyMessageConsumer@28761658[sub=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create] CLOSED listening=true receiving=false sessionConsumer=false waitingForMessage=true messages=0 thread=Thread[MessageListenerThread - anyRemoteGSQueuePOKER,5,JBossMQ Client Threads] listener=GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744465 session=SpySession@4147818[tx=false ack=AUTO txid=null RUNNING connection=Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd rcvstate=STARTED]]]
09:15:44,466 -org.jboss.mq.SpyMessageConsumer Consumer closed while waiting in run() SpyMessageConsumer@28761658[sub=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create] CLOSED listening=true receiving=false sessionConsumer=false waitingForMessage=false messages=0 thread=Thread[MessageListenerThread - anyRemoteGSQueuePOKER,5,JBossMQ Client Threads] listener=GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744466 session=SpySession@4147818[tx=false ack=AUTO txid=null RUNNING connection=Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd rcvstate=STARTED]]]
09:15:44,466 -org.jboss.mq.SpyMessageConsumer Joining listener thread. SpyMessageConsumer@28761658[sub=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create] CLOSED listening=true receiving=false sessionConsumer=false waitingForMessage=false messages=0 thread=Thread[MessageListenerThread - anyRemoteGSQueuePOKER,5,] listener=GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744466 session=SpySession@4147818[tx=false ack=AUTO txid=null RUNNING connection=Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd rcvstate=STARTED]]]
09:15:44,466 -org.jboss.mq.Connection removeConsumer req=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create]
09:15:44,466 -org.jboss.mq.il.uil2.SocketManager Begin internalSendMessage, round-trip msg=org.jboss.mq.il.uil2.msgs.UnsubscribeMsg19881206[msgType: m_unsubscribe, msgID: 5819060, error: null]
09:15:44,466 -org.jboss.mq.il.uil2.SocketManager Write msg: org.jboss.mq.il.uil2.msgs.UnsubscribeMsg19881206[msgType: m_unsubscribe, msgID: 5819060, error: null]
09:15:44,467 -org.jboss.mq.il.uil2.SocketManager Read msgType: m_unsubscribe, msgID: 5819060
09:15:44,467 -org.jboss.mq.il.uil2.SocketManager Found replyMap msg: org.jboss.mq.il.uil2.msgs.UnsubscribeMsg19881206[msgType: m_unsubscribe, msgID: 5819060, error: null]
09:15:44,467 -org.jboss.mq.il.uil2.SocketManager Read msg reply: org.jboss.mq.il.uil2.msgs.UnsubscribeMsg19881206[msgType: m_unsubscribe, msgID: 5819060, error: null]
09:15:44,467 -org.jboss.mq.il.uil2.SocketManager End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.UnsubscribeMsg19881206[msgType: m_unsubscribe, msgID: 5819060, error: null]
09:15:44,467 -org.jboss.mq.SpySession Remove consumer SpyMessageConsumer@28761658[sub=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create] CLOSED listening=true receiving=false sessionConsumer=false waitingForMessage=false messages=0 thread=Thread[MessageListenerThread - anyRemoteGSQueuePOKER,5,] listener=GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744467 session=SpySession@4147818[tx=false ack=AUTO txid=null RUNNING connection=Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd rcvstate=STARTED]]]
09:15:44,468 -org.jboss.mq.SpyMessageConsumer Closed. SpyMessageConsumer@28761658[sub=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create] CLOSED listening=true receiving=false sessionConsumer=false waitingForMessage=false messages=0 thread=Thread[MessageListenerThread - anyRemoteGSQueuePOKER,5,] listener=GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744468 session=SpySession@4147818[tx=false ack=AUTO txid=null RUNNING connection=Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd rcvstate=STARTED]]]
09:15:44,468 -JMS_LOGGER GSJMSMessageListener:close:GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744468
09:15:44,468 -JMS_LOGGER JMS: JMSMsgReceiver:close:[JMSMsgReceiver::10.1.128.85:2QueueMtct:true]I have lighted client ids on connection object we set.
Q_2_POKER_10.1.128.88_223
Q_2_POKER_10.1.128.88_4682
1st connection is created long back and doesnt close and cause onException() method being called which inturn causes many connections being created. we share same exception listener on any new connection we create. even after server restart first connection still remains at client and causes onException() being invoked repeatively.
can you help us?
-
19. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Can you post the extra logging after this:
"
09:15:44,468 -org.jboss.mq.SpyMessageConsumer Closed. SpyMessageConsumer@28761658[sub=Subscription[subId=-2147483648connection=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd destination=QUEUE.anyRemoteGSQueuePOKER messageSelector=null Local Create] CLOSED listening=true receiving=false sessionConsumer=false waitingForMessage=false messages=0 thread=Thread[MessageListenerThread - anyRemoteGSQueuePOKER,5,] listener=GSJMSMessageListener:JMSMsgReceiver10.1.128.85anyRemoteGSQueue:0:1269263744468 session=SpySession@4147818[tx=false ack=AUTO txid=null RUNNING connection=Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd rcvstate=STARTED]]]
"
I want to see what happened when it closed the connection, this will be after it closed the consumer.
There should be something stating it has closed the socket, which should send an RST packet (connection reset) to the server to close its side.
I can't read your attachment, when I unzip it, it is a binary file.
Even so, if the client has stopped sending the pings or other messages the server should close the serverside socket due to inactivity
on the socket read timeout.
It said it failed to receive the pong in the first line you posted, that doesn't mean however that the ping didn't get to the server,
only that the pong never arrived back from it in time. Can you see any IOExecptions around about the time you posted the log snippet?
-
20. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Actually, I can tell from the log that you are closing the consumers manually,
rather than using Connection.close() to do it.
That is because there is no logging from org.jboss.mq.SpyConnection or org.jboss.mq.SpySession saying they are being closed
before it closes the MessageConsumer.
Are you sure you are actually closing the connections? There should be some TRACE logging saying so if you are.
-
21. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Adrian Brock wrote:
It said it failed to receive the pong in the first line you posted, that doesn't mean however that the ping didn't get to the server,only that the pong never arrived back from it in time. Can you see any IOExecptions around about the time you posted the log snippet?
The ping timeout seems to be spurious anyway, you can see it successfully sending a consumer unsubscribe message to the server
and getting a reply. See the FAQ for possible reasons:
http://community.jboss.org/wiki/IGetIOExceptionPingTimeoutHowDoIFixIt
-
22. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
leela mahesh wrote:
Is it possible that putting huge messages on queue may delay pong on the respective connection?
<snip/><!-- A pong is simulated after each chunk (in bytes) for both reading and writing -->
<!-- It must be larger than the buffer size -->
<attribute name="ChunkSize">1000000</attribute> New Value: 100000 (100 KB)
will there be any side effects with the above configuration? will there be any issues if we receive pong before ping has been sent as I set chunk size to 100KB?
This configuration will simulate a pong every time 100,000 bytes is sent/received over the network connection.
Receiving mulitple pongs is not a problem. Having a ping/pong waiting to go over the network is. ;-)
But that isn't the real problem. I suspect you ExceptionListener is failing to close what it thinks is a broken connection.
So avoiding the spurious ping timeout only moves the problem to when it is really a broken connection.
-
23. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Adrian,
I have attached log file again. could you please check once?
we first close clients. our clients are wrapper again on each destination. after closing clients we close connection. we recreate connection and recreate all destinations again.
One particular rogue connection which is not there at server end but still there at client end causing onException() being invoked repeatedly. But that connection should be closed as per client timeout which is not happening in this case. could you check once if there is any issue?
-
24. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
It looks to me like you are closing the wrong connection.
e.g.
09:15:44,462 -org.jboss.mq.Connection Notified of failure reason=Unexpected ping failure Connection@5404683[token=ConnectionToken:Q_2_POKER_10.1.128.88_223/5
9280ad739196008f4ff7224868734d2 rcvstate=STOPPED]
org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)But you are then closing
09:15:44,472 -org.jboss.mq.Connection Stopping connection Connection@6039074[token=ConnectionToken:Q_2_POKER_10.1.128.88_4682/5b2c2b5171e52ccf5c98cedb2833c9fd CLOSING rcvstate=STOPPED]
You can see later that you get a repeated failure of the ping since you have not closed the connection that has failed.
09:16:44,473 -org.jboss.mq.Connection Notified of failure reason=Unexpected ping failure Connection@5404683[token=ConnectionToken:Q_2_POKER_10.1.128.88_223/5
9280ad739196008f4ff7224868734d2 rcvstate=STOPPED]
org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)So the discussion above is probably not about a spurious ping afterall.
-
25. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
Adrian,
Q_2_POKER_10.1.128.88_223 is very old connection. May be due to some issue in our code we are unable to close it. but even though we dont close it, it should be closed after client time out happens which is 120 seconds here. do you see any issue why this connection is not closed automatically? we see this connection is in TIMED_WAITING from netstat on linux box.
-
26. Re: JBoss 4.2.2 - Unable to read messages from queue or topic after some days server is started
leela mahesh wrote:
Adrian,
Q_2_POKER_10.1.128.88_223 is very old connection. May be due to some issue in our code we are unable to close it. but even though we dont close it, it should be closed after client time out happens which is 120 seconds here. do you see any issue why this connection is not closed automatically? we see this connection is in TIMED_WAITING from netstat on linux box.
I'm not an expert of TIMED_WAITING, but I think you'll find that because you haven't invoked Connection.close()
it hasn't done Socket.close() which means TCP/IP thinks there could potentially be packets still going over the network.
The TIMED_WAITING state is designed to "hog" the host/port to avoid delayed packets going to a later different connection on the same host/port.
The read timeout on the client must have occurred otherwise it wouldn't be in the TIMED_WAITING state (i.e. it thinks it is closed on this side
of the connection).
The issue with your code is probably that you don't have the Connection.close() in a finally block.
e.g. You need something like:
Connection c = ...;
public void onException(JMSException e)
{
try
{
// Here you try to close consumers/sessions, etc.
}
finally
{
// Always close the connection, even if there is an error above
c.close();
}
// Reconect here.
}
