SingleConnectionFactory's resetConnection is causing deadlocks with underlying OracleAQ's JMS connection [SPR-5987]

[spring-projects-issues]

Rajani Chennamaneni opened SPR-5987 and commented

We had encountered below deadlock using the Spring 2.5.6 jar.

"DefaultMessageListenerContainer-303263" prio=10 tid=0x081be000 nid=0x5e74 waiting for monitor entry [0xb0698000..0xb0698ea0]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jms.AQjmsExceptionListener.resumeExceptionListener(AQjmsExceptionListener.java:235)

• waiting to lock <0x56154178> (a oracle.jms.AQjmsExceptionListener)
  at oracle.jms.AQjmsConnection.start(AQjmsConnection.java:498)
• locked <0x5614ec28> (a oracle.jms.AQjmsConnection)
  at org.springframework.jms.connection.SingleConnectionFactory$SharedConnectionInvocationHandler.invoke(SingleConnectionFactory.java:514)
  at $Proxy29.start(Unknown Source)
  at org.springframework.jms.connection.ConnectionFactoryUtils.doGetTransactionalSession(ConnectionFactoryUtils.java:277)
  at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:286)
  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.run(DefaultMessageListenerContainer.java:881)
  at java.lang.Thread.run(Thread.java:619)

"Thread-336" prio=10 tid=0x0852e800 nid=0x489e waiting for monitor entry [0xaf0b0000..0xaf0b10a0]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jms.AQjmsConnection.stop(AQjmsConnection.java:520)

• waiting to lock <0x5614ec28> (a oracle.jms.AQjmsConnection)
  at org.springframework.jms.connection.SingleConnectionFactory.closeConnection(SingleConnectionFactory.java:423)
  at org.springframework.jms.connection.SingleConnectionFactory.resetConnection(SingleConnectionFactory.java:322)
• locked <0x5556c840> (a java.lang.Object)
  at org.springframework.jms.connection.CachingConnectionFactory.resetConnection(CachingConnectionFactory.java:199)
  at org.springframework.jms.connection.SingleConnectionFactory.onException(SingleConnectionFactory.java:303)
  at org.springframework.jms.connection.ChainedExceptionListener.onException(ChainedExceptionListener.java:60)
  at oracle.jms.AQjmsExceptionListener.onException(AQjmsExceptionListener.java:148)
• locked <0x56154178> (a oracle.jms.AQjmsExceptionListener)
  at oracle.jms.AQjmsExceptionListener.run(AQjmsExceptionListener.java:223)

We then patched SingleConnectionFactory.java for the change made in Revision 1500 (https://fisheye.springsource.org/browse/spring-framework/trunk/org.springframework.jms/src/main/java/org/springframework/jms/connection/SingleConnectionFactory.java?r2=1500&r1=674) of this class in truck in our project. I will attach the patched file to this issue as well. This patch we did also includes an additional log statement in "onException" method to log the JMSException. It would be nice if you can add that log statement for next release.

Even after the patch of moving the "this.target.start()" statement inside the synchronized block, we still encountered deadlock as below:

Name: DefaultMessageListenerContainer-43803
State: BLOCKED on oracle.jms.AQjmsExceptionListener@a77e20 owned by: Thread-92
Total blocked: 1 Total waited: 0

Stack trace:
oracle.jms.AQjmsExceptionListener.resumeExceptionListener(AQjmsExceptionListener.java:235)
oracle.jms.AQjmsConnection.start(AQjmsConnection.java:498)

• locked oracle.jms.AQjmsConnection@1c15642
  org.springframework.jms.connection.SingleConnectionFactory$SharedConnectionInvocationHandler.invoke(SingleConnectionFactory.java:517)
• locked java.lang.Object@91d649
  $Proxy29.start(Unknown Source)
  org.springframework.jms.connection.ConnectionFactoryUtils.doGetTransactionalSession(ConnectionFactoryUtils.java:277)
  org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:286)
  org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:241)
  org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:982)
  org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:881)
  java.lang.Thread.run(Thread.java:619)

Name: Thread-92
State: BLOCKED on java.lang.Object@91d649 owned by: DefaultMessageListenerContainer-43803
Total blocked: 1 Total waited: 42

Stack trace:
org.springframework.jms.connection.SingleConnectionFactory.resetConnection(SingleConnectionFactory.java:322)
org.springframework.jms.connection.CachingConnectionFactory.resetConnection(CachingConnectionFactory.java:199)
org.springframework.jms.connection.SingleConnectionFactory.onException(SingleConnectionFactory.java:304)
org.springframework.jms.connection.ChainedExceptionListener.onException(ChainedExceptionListener.java:60)
oracle.jms.AQjmsExceptionListener.onException(AQjmsExceptionListener.java:148)

• locked oracle.jms.AQjmsExceptionListener@a77e20
  oracle.jms.AQjmsExceptionListener.run(AQjmsExceptionListener.java:223)

My suggestion is to make the call to target's start method only if it wasn't already started. The code would like below:

            synchronized (connectionMonitor) {
     if (!started) { //if condition added to avoid possible deadlocks when trying to reset the target connection
              this.target.start();
              started = true;
     }
}

Please look into this and let me know what you think of the change and address it accordingly in the next release.

---

Affects: 2.5.6

Attachments:

• SingleConnectionFactory.java (21.01 kB)

Referenced from: commits 6e25ca8, 23a1d07, 83bd56c

[spring-projects-issues]

Rajani Chennamaneni commented

Attaching the patch we used that caused the second set of deadlock traces I mentioned in the description.

Also, My fix suggestion code block didn't render correctly in the description above.

synchronized (connectionMonitor) {
//if condition added to avoid possible deadlocks when trying to reset the target connection
if (!started) {
this.target.start();
started = true;
}
}

[spring-projects-issues]

Juergen Hoeller commented

Good point - we can certainly call start just when actually necessary there. I changed this as of 3.0 M4.

Juergen

[spring-projects-issues]

Rajani Chennamaneni commented

Thanks Juergen for fixing this so soon :).

Can you also consider adding a log statement in "SingleConnectionFactory.onException" method to log the JMSException it receives. Currently its eating it up making it impossible to see what caused the resetConnection.

Thanks.