c.s.j.v750.ConnectionImpl.increaseDuplicateLogSize generates IndexOutOfBoundsException

[batalbot]

On several occasions, a particular swiftmq client application has locked up after running for a few weeks.  The spring application gets into a loop attempting to refresh its JMS connection and it always fails with the exception shown below.  Note that this seems to take many days to a few weeks to occur and the application runs correctly until then.

The client is bound to a clustered queue with 2 physical queues bound to the clustered queue.

This is occurring on swiftmq 7.5.1


2009-08-17 13:16:52,531 [gameItemJmsContainer-1] DEBUG org.springframework.jms.listener.DefaultMessageListenerContainer - Initiating transaction rollback on listener exception
java.lang.IndexOutOfBoundsException: Index: 0, Size: 0
        at java.util.LinkedList.entry(LinkedList.java:365)
        at java.util.LinkedList.remove(LinkedList.java:357)
        at com.swiftmq.tools.collection.ListSet.resize(Unknown Source)
        at com.swiftmq.jms.v750.ConnectionImpl.increaseDuplicateLogSize(Unknown Source)
        at com.swiftmq.jms.v750.SessionImpl.addMessageConsumerImpl(Unknown Source)
        at com.swiftmq.jms.v750.SessionImpl.createReceiver(Unknown Source)
        at com.swiftmq.jms.v750.SessionImpl.createConsumer(Unknown Source)
        at com.swiftmq.jms.v750.SessionImpl.createConsumer(Unknown Source)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.createConsumer(AbstractPollingMessageListenerContainer.java:477)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.createListenerConsumer(AbstractPollingMessageListenerContainer.java:221)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:305)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:241)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:974)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:876)
        at java.lang.Thread.run(Thread.java:619)

[IIT Software]

The only way to get the above exception is a concurrent clear() of the duplicate log while the increaseDuplicateLogSize() is performed. The only points of calling clear() is in connection.close() and internal cancel().

Do you call connection.close() concurrently?

Why don't you use our springsupport library?

[batalbot]

Once the exception occurs, the application tries to recover.  From looking at the logs it looks like spring attempts to get a new connection from JNDI; however, the application keeps receiving the "java.lang.IndexOutOfBoundsException: Index: 0, Size: 0" exception.  The application goes into a loop and stops processing messages while its failing and getting the exceptions.

One interesting thing is that two instances of the application which were started at about the same time both failed in this same way within 30 minutes of each other.  Each application instance was bound to a different SwiftMQ instance.

The SwiftMQ info logs are pretty quiet until this occurs and then they are filled with connections to the JNDI port:

2009-08-17 14:43:15.602/[NioTCPListener, swiftlet=sys$jms, port=4101]/INFORMATION/connection accepted: 127.0.0.1
2009-08-17 14:43:15.720/sys$jms/INFORMATION/JMSConnection v750/127.0.0.1:50928/receiving disconnect request, scheduling connection close
2009-08-17 14:43:15.722/127.0.0.1:50928/NioHandler/INFORMATION/exception, EXITING: java.io.IOException: channel reports end-of-stream
2009-08-17 14:43:15.722/127.0.0.1:50928/NioHandler/INFORMATION/close
2009-08-17 14:43:15.752/sys$jms/INFORMATION/JMSConnection v750/127.0.0.1:50928/connection closed
2009-08-17 14:43:16.81/[NioTCPListener, swiftlet=sys$jms, port=4101]/INFORMATION/connection accepted: 127.0.0.1
2009-08-17 14:43:16.200/sys$jms/INFORMATION/JMSConnection v750/127.0.0.1:50929/receiving disconnect request, scheduling connection close
2009-08-17 14:43:16.202/127.0.0.1:50929/NioHandler/INFORMATION/exception, EXITING: java.io.IOException: channel reports end-of-stream
2009-08-17 14:43:16.202/127.0.0.1:50929/NioHandler/INFORMATION/close
2009-08-17 14:43:16.202/sys$jms/INFORMATION/JMSConnection v750/127.0.0.1:50929/connection closed
...



From what I can tell, the JMS connection remains open until the application is eventually stopped.

2009-07-23 21:10:59.940/[NioTCPListener, swiftlet=sys$jms, port=4100]/INFORMATION/connection accepted: 111.222.0.225
...
2009-08-17 15:32:46.935/sys$jms/INFORMATION/JMSConnection v750/111.222.0.225:39961/receiving disconnect request, scheduling connection close
2009-08-17 15:32:46.936/111.222.0.225:39961/NioHandler/INFORMATION/exception, EXITING: java.io.IOException: channel reports end-of-stream
2009-08-17 15:32:46.936/111.222.0.225:39961/NioHandler/INFORMATION/close
2009-08-17 15:32:47.463/sys$jms/INFORMATION/JMSConnection v750/111.222.0.225:39961/connection closed


connection.close() is never being called as far as I can tell.

[IIT Software]

It is a concurrency problem. The only way to fire nonsynchronized into this resize operation is via close or internal cancel (connection lost, max-retry reached).

Are you able to use our spring support library? If yes, please do so. The lib handles all spring JMS stuff properly, provides pooling and we can debug it, if necessary.

[batalbot]

I'll configure a test system to use springsupport and see what happens.  It takes 3 weeks to reproduce normally.  Any special settings I need to use to enable debugging in case it does happen again?

Note that we have a few applications using the spring caching connection factories and this problem does not occur with them -- they are using topics and not clustered queue though.  They're also not using request-reply.

[IIT Software]

I suggest to let debug disable for now (it's the system prop mentioned in the doc page). I don't think it will happen again. Let me know how it goes...