Receiving IllegalStateExceptions in client

[bander]

Hello

I'm performing a series of JMS stress tests that we've developed against JBoss Messaging 1.0.1.SP4 and have a test scenario failing. My particular test is generating frequent IllegalStateExceptions which causes message delivery to fail. The following is a sample:

ERROR 2007-02-14 16:30:58,984 [Manager Queue Eight.1.4] org.jboss.jms.client.remoting.MessageCallbackHandler: Failed to deliver message
javax.jms.IllegalStateException: Should only be one entry in list. There are 8908
at org.jboss.jms.client.container.SessionAspect.handlePostDeliver(SessionAspect.java:203)
at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect6.invoke(SessionAspect6.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:182)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:117)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:69)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate.postDeliver(ClientSessionDelegate.java)
at org.jboss.jms.client.remoting.MessageCallbackHandler.postDeliver(MessageCallbackHandler.java:162)
at org.jboss.jms.client.remoting.MessageCallbackHandler.callOnMessage(MessageCallbackHandler.java:137)
at org.jboss.jms.client.remoting.MessageCallbackHandler$ListenerRunner.run(MessageCallbackHandler.java:722)
at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(Unknown Source)
at java.lang.Thread.run(Thread.java:534)



Essentially, this test does the following:

1. creates a set of text message payloads
2. creates a set of object message payloads
3. dispatches the message payloads to separate queues using a multi-threaded dispatcher (the multi-threaded dispatcher obtains a jms session from a jms session pool)
4. at the same time, it receives the messages arriving on the queues using a multi-threaded message listener
5. it then compares the payloads received on the text queue with the payloads dispatched to that queue (and likewise for the object queue)

So far we've found 1.0.1.SP4 is a big improvement over the 1.0.1.GA release (we used to get messages arriving on the wrong queues on older versions for some of our tests) but this test in particular is still causing problems for JBoss Messaging.

Can any JBoss developers explain the significance of 'Should only be one entry in list. There are 8908'?

[timfox]

This has come up several times before, and if I remember correctly, almost every time has been due to people sharing the session between multiple threads.

JMS sessions are supposed to be used by only one thread at a time so this would be illegal.

Can you confirm you're not doing stuff with the session with multiple threads at the same time?

E.g. two consumers on the same session, and calling consumer.receive(..) in different threads, or two producers on the same session and sending conurrently on different threads?

[timfox]

See JMS1.1 spec section 4.4, especially 4.4.6, e.g.:

"Sessions are designed for serial use by one thread at a time. The only exception
to this occurs during the orderly shutdown of the session or its connection. See
Section 4.3.5 ?Closing a Connection,? and Section 4.4.1 ?Closing a Session,? for
further details.
One typical use is to have a thread block on a synchronous MessageConsumer
until a message arrives. The thread may then use one or more of the session?s
MessageProducers.
It is erroneous for a client to use a thread of control to attempt to
synchronously receive a message if there is already a client thread of control
waiting to receive a message in the same session."

[timfox]

http://www.jboss.com/index.html?module=bb&op=viewtopic&t=98881&view=previous

[ovidiu.feodorov]

I annotated http://jira.jboss.com/jira/browse/JBMESSAGING-752, I will personally add a section in FAQs that explains how sessions must be accessed by a single thread at one time.

[bander]

We're not using multiple threads per session.

On the receiving side (where this exception has been thrown), a single thread is used to create 5 sessions. Each session has a single consumer.

The relevant receiving code is as follows:

setConnectionFactory(getConnectionFactoryStrategy()
 .createConnectionFactory());
LOG.info(getName() + " JMS connection factory created");
LOG.info(getName() + " creating JMS connection");
connection = getConnectionFactory().createConnection();
connection.setExceptionListener(//
 createExceptionListener(manager));
LOG.info(getName() + " JMS connection created");
LOG.info(getName() + " creating "
 + getNumberOfProcesses()
 + " message consumer processes");
consumers = new MessageConsumer[getNumberOfProcesses()];
sessions = new Session[getNumberOfProcesses()];

for (int x = 0; x < consumers.length; x++) {
 if (LOG.isDebugEnabled()) {
 LOG.debug(getName()
 + " starting receive process " + x);
 }
 sessions[x] = connection.createSession(false,
 Session.AUTO_ACKNOWLEDGE);
 Queue q = sessions[x].createQueue(getQueueName());

 consumers[x] = sessions[x].createConsumer(q);
 consumers[x]
 .setMessageListener(createMessageListener(
 sessions[x], x));
 if (LOG.isDebugEnabled()) {
 LOG.debug(getName() + " receive process " + x
 + " started");
 }
}
LOG.info(getName() + " starting JMS connection");
connection.start();

Each of our queues has it's own thread to create these sessions but once created they are only accessed by that thread.

[bander]

Interesting - I reconfigured our test to only use one consumer per session per receiver thread and it ran without generating the IllegalStateException (previously I was using 5 consumers per session per receiver thread).

It looks like the jboss client may be choking on sessions that have multiple consumers, even if the session is only being used by one thread - according to the jms spec I should be able to do this (4.4.6 Conventions for Using a Session).

I'll run a longer test and post the results back.

[timfox]

If you can replicate the issue in a simple test case with real code, that would be helpful.

So you're creating a set of message listeners on the same session, and you're saying this gives you the aforementioned problem?

What are you doing in your message listeners? Are you accessing the session at all?

[bander]

"timfox" wrote:

So you're creating a set of message listeners on the same session, and you're saying this gives you the aforementioned problem?

What are you doing in your message listeners? Are you accessing the session at all?

No sorry. I've got that wrong.

We're using a single thread to create a set of sessions. Each session has a single consumer (not multiple consumers per session as I stated earlier). Each consumer is configured with a message listener.

Previously our test was using a single thread to create 5 sessions, with one consumer/listener per session. This was causing frequent IllegalStateExceptions.

When I reconfigured the test to only create one session, with one consumer/listener the problem appears to go away.

The message listener used by each consumer is actually a singleton that simply stores the received payload so we can compare it with what was sent at the end of the test:

 public void onMessage(Message message) {
 // extract payload and received queue name and pass to test coordinator
 // for processing
 try {
 String queueName = ((Queue) message.getJMSDestination())
 .getQueueName();
 Object payload = null;
 if (message instanceof TextMessage) {
 payload = ((TextMessage) message).getText();
 } else if (message instanceof ObjectMessage) {
 payload = ((ObjectMessage) message).getObject();
 } else {
 throw new RuntimeException(
 "Received unexpected JMS message type: "
 + message.getClass());
 }
 getMessageStore().store(queueName, payload);
 } catch (Exception ex) {
 throw new RuntimeException(//
 "Failed to process received message", ex);
 }
 }

[bander]

Just to sum things up - the following receiver code appears to work ok under jboss messaging:

Session session = connection.createSession(false,
 Session.AUTO_ACKNOWLEDGE);
Queue q = session.createQueue(getQueueName());

MessageConsumer consumer = session.createConsumer(q);
consumer.setMessageListener(getMessageListener());

The following receiver code will result in IllegalStateExceptions under jboss messaging:

consumers = new MessageConsumer[5];
sessions = new Session[5];

for (int x = 0; x < consumers.length; x++) {
 sessions[x] = connection.createSession(false,
 Session.AUTO_ACKNOWLEDGE);
 Queue q = sessions[x].createQueue(getQueueName());

 consumers[x] = sessions[x].createConsumer(q);
 consumers[x].setMessageListener(getMessageListener());
}

Is the code above is violating the jms spec? (the test that uses this code does work on other JMS server implementations e.g. Sun Messaging - but that has its own issues).

[bander]

I've just discovered something else too. The IllegalStateException we have been seeing may be the result of a previous failure in JBoss. After doing some more tests I found the following errors in the log:

ERROR 2007-02-15 17:49:52,687 [Manager Queue Seven.1.0] org.jboss.jms.client.container.ExceptionInterceptor: Linked exception is:
org.jboss.remoting.CannotConnectException: Can not get connection to server. Problem establishing socket connection for InvokerLocator [socket://172.26.1.240:4457/?clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.server.remoting.JMSWireFormat&serializationtype=jboss&socket.check_connection=false&unmarshaller=org.jboss.jms.server.remoting.JMSWireFormat]
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:510)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:122)
at org.jboss.remoting.Client.invoke(Client.java:1414)
at org.jboss.remoting.Client.invoke(Client.java:511)
at org.jboss.jms.client.delegate.DelegateSupport.invoke(DelegateSupport.java:111)
at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledge_354868566256058116.invokeNext(ClientSessionDelegate$acknowledge_354868566256058116.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:182)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:117)
at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledge_354868566256058116.invokeNext(ClientSessionDelegate$acknowledge_354868566256058116.java)
at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:69)
at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledge_354868566256058116.invokeNext(ClientSessionDelegate$acknowledge_354868566256058116.java)
at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledge_354868566256058116.invokeNext(ClientSessionDelegate$acknowledge_354868566256058116.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate.acknowledge(ClientSessionDelegate.java)
at org.jboss.jms.client.container.SessionAspect.handlePostDeliver(SessionAspect.java:215)
at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect6.invoke(SessionAspect6.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:182)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:117)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:69)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate.postDeliver(ClientSessionDelegate.java)
at org.jboss.jms.client.remoting.MessageCallbackHandler.postDeliver(MessageCallbackHandler.java:162)
at org.jboss.jms.client.remoting.MessageCallbackHandler.callOnMessage(MessageCallbackHandler.java:137)
at org.jboss.jms.client.remoting.MessageCallbackHandler$ListenerRunner.run(MessageCallbackHandler.java:722)
at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(Unknown Source)
at java.lang.Thread.run(Thread.java:534)
Caused by: java.net.SocketException: Can not obtain client socket connection from pool. Have waited 30 seconds for available connection (50 in use)
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.getConnection(MicroSocketClientInvoker.java:776)
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:506)
... 29 more
ERROR 2007-02-15 17:49:52,703 [Manager Queue Seven.1.0] org.jboss.jms.client.remoting.MessageCallbackHandler: Failed to deliver message
javax.jms.IllegalStateException: Can not get connection to server. Problem establishing socket connection for InvokerLocator [socket://172.26.1.240:4457/?clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.server.remoting.JMSWireFormat&serializationtype=jboss&socket.check_connection=false&unmarshaller=org.jboss.jms.server.remoting.JMSWireFormat]
at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:91)
at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledge_354868566256058116.invokeNext(ClientSessionDelegate$acknowledge_354868566256058116.java)
at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledge_354868566256058116.invokeNext(ClientSessionDelegate$acknowledge_354868566256058116.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate.acknowledge(ClientSessionDelegate.java)
at org.jboss.jms.client.container.SessionAspect.handlePostDeliver(SessionAspect.java:215)
at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect6.invoke(SessionAspect6.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:182)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:117)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:69)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate.postDeliver(ClientSessionDelegate.java)
at org.jboss.jms.client.remoting.MessageCallbackHandler.postDeliver(MessageCallbackHandler.java:162)
at org.jboss.jms.client.remoting.MessageCallbackHandler.callOnMessage(MessageCallbackHandler.java:137)
at org.jboss.jms.client.remoting.MessageCallbackHandler$ListenerRunner.run(MessageCallbackHandler.java:722)
at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(Unknown Source)
at java.lang.Thread.run(Thread.java:534)
ERROR 2007-02-15 17:49:52,703 [Manager Queue Seven.1.0] org.jboss.jms.client.remoting.MessageCallbackHandler: Failed to deliver message
javax.jms.IllegalStateException: Should only be one entry in list. There are 2
at org.jboss.jms.client.container.SessionAspect.handlePostDeliver(SessionAspect.java:203)
at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect6.invoke(SessionAspect6.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:182)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:117)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ExceptionInterceptor.invoke(ExceptionInterceptor.java:69)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.container.ClientLogInterceptor.invoke(ClientLogInterceptor.java:107)
at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_5319211143798977162.invokeNext(ClientSessionDelegate$postDeliver_5319211143798977162.java)
at org.jboss.jms.client.delegate.ClientSessionDelegate.postDeliver(ClientSessionDelegate.java)
at org.jboss.jms.client.remoting.MessageCallbackHandler.postDeliver(MessageCallbackHandler.java:162)
at org.jboss.jms.client.remoting.MessageCallbackHandler.callOnMessage(MessageCallbackHandler.java:137)
at org.jboss.jms.client.remoting.MessageCallbackHandler$ListenerRunner.run(MessageCallbackHandler.java:722)
at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(Unknown Source)
at java.lang.Thread.run(Thread.java:534)

Note how we start to get the 'Should only be one entry in list...' error after the socket exception.

Doing a search for the 'Can not get connection to server...' error uncovered this issue:

http://jira.jboss.com/jira/browse/JBMESSAGING-771

Is it possible we're experiencing this issue in 1.0.1.SP4?

Maybe this is why reducing the number of sessions our receivers are opening (from 5 to 1) stops the error from occuring?

[timfox]

Please can you send me your test case (or a small java program) that gives the exception and I'll investigate further.

Thx

[bander]

Tim,

I've emailed you a modified version of the QueueExample class from the JBoss Messaging examples that displays the behaviour I've been observing.

We're testing JBoss 1.0.1.SP4 on Windows XP with a MySQL backend (using the InnoDB engine - also on Windows XP). The test queue should be configured with the following settings: fullSize = 10000 pageSize = 2000 downCacheSize = 2000.

If anyone else is interested, I'll post the modified QueueExample class here.

[timfox]

Ben -

I have run your example using 1.0.1.SP4, Windows XP, MySQL, InnoDB and with your paging settings, and I see no exceptions on the client side or in the server side logs:

run:
 [java] Attempting to send 20000 messages to the testQueue queue...
 [java] 1000 messages sent to server...
 [java] 2000 messages sent to server...
 [java] 3000 messages sent to server...
 [java] 4000 messages sent to server...
 [java] 5000 messages sent to server...
 [java] 6000 messages sent to server...
 [java] 7000 messages sent to server...
 [java] 8000 messages sent to server...
 [java] 9000 messages sent to server...
 [java] 10000 messages sent to server...
 [java] 11000 messages sent to server...
 [java] 12000 messages sent to server...
 [java] 13000 messages sent to server...
 [java] 14000 messages sent to server...
 [java] 15000 messages sent to server...
 [java] 16000 messages sent to server...
 [java] 17000 messages sent to server...
 [java] 18000 messages sent to server...
 [java] 19000 messages sent to server...
 [java] 20000 messages sent to server...
 [java] Finished sending 20000 messages to the testQueue queue
 [java] About to start 10 connections with 50 sessions per connection...
 [java] Connections started. Will allow 120000 milliseconds for listeners to
 receive all messages...

 [java] #####################
 [java] ### SUCCESS! ###
 [java] #####################

BUILD SUCCESSFUL
Total time: 2 minutes 18 seconds

[timfox]

I think what you are seeing is a network problem between your client and server that is preventing the acknowledgement going through.

Looking at the code SessionAspect::handlePostDeliver:

 if (cancel)
 {
 sd.cancelDeliveries(acks);
 }
 else
 {
 sd.acknowledge(ack);
 }
 state.getToAck().clear();

The unacked message state is not cleared if the acknowledge throws an exception, so this would explain why the next call to handlePostDeliver gives you an IllegalStateException.