Connections being intermittently left open on JBoss for requests from clients

Connections being intermittently left open on JBoss for requests from clients

The issue I'm having is that occasionally a connection for a clientside
request + the assosiated DB connection (using Oracle 10g RAC) get left
open on JBoss EAP 4.3.0 CP10. Also a JBM JMS queue dealing with messages
bound back to the server from and external service related to the request
gains messages that seem to stay in delivering state awfully long if not
infinitely (DeliveringCount keeps abnormally high).
So far no errors have been found anywhere to explain this, and the only
way to work around it is to restart JBoss when the connection pools are
starting to get full. The "hanging" of the request processing occurs quite
rarely, my estimate is that it happens for less than 0,01% of requests,
but curiously enough it only happens for certain kind of requests (getting
a live position for an object in the system).
It's a closed-source application but as I have understood things go
roughly like this:
the client sends a HTTP request to the server (via Apache proxy talking
AJP to the AS)
the server sends a request to a positioning service via JMS
the positioning service responds with the most recent data it has (should
happen within 1 sec)
the server responds to the client with the position data
There would seem to be some activity also with the object persistence DB
of the application although it really does not store the live position on
the object. Anyhow, no matter the reason for having also the DB connection
open during the request-response process, both the AJP connection and the
DB connection are left open without ever finalising the transaction. The
AJP connection is waiting for a lock from another AJP thread which has
already gone doing something else. Below is a sample stack trace extracted
with jconsole for a thread that is waiting eternally.
Name: ajp-0.0.0.0-8009-148
State: WAITING on
java.util.concurrent.locks.ReentrantLock$FairSync@285b829d owned by:
ajp-0.0.0.0-8009-100
Total blocked: 7 344 Total waited: 7 146
Stack trace:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178)
java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:201)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
org.jboss.resource.adapter.jms.JmsManagedConnection.lock(JmsManagedConnection.java:393)
org.jboss.resource.adapter.jms.JmsXAResource.prepare(JmsXAResource.java:82)
org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.prepare(JcaXAResourceWrapper.java:93)
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:271)
com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2880)
com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2837)
com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2389)
- locked
com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction@6204cae5
com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1785)
- locked
com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction@6204cae5
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
com.arjuna.ats.arjuna.AtomicAction.end(AtomicAction.java:216)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:240)
org.jboss.ejb.plugins.TxInterceptorCMT.endTransaction(TxInterceptorCMT.java:501)
org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:361)
org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)
org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:168)
org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:648)
org.jboss.ejb.Container.invoke(Container.java:960)
sun.reflect.GeneratedMethodAccessor149.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:169)
org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:118)
org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:209)
org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:195)
org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:61)
org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:70)
org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:112)
org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:100)
$Proxy148.getPositions(Unknown Source)
<<<a call for the getPositions() method>>>
sun.reflect.GeneratedMethodAccessor155.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java:402)
org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.java:309)
org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:333)
org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:71)
org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:150)
org.apache.axis.SimpleChain.invoke(SimpleChain.java:120)
org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:481)
org.apache.axis.server.AxisServer.invoke(AxisServer.java:323)
org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:854)
javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.java:339)
javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
com.osmoticweb.gzipfilter.GZIP2WayFilter.doFilter(GZIP2WayFilter.java:54)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:173)
org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:525)
org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:241)
org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:419)
org.apache.coyote.ajp.AjpAprProtocol$AjpConnectionHandler.process(AjpAprProtocol.java:393)
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1513)
java.lang.Thread.run(Thread.java:662)
I have waded through the JBoss issue tracker without finding a matching
case, and I have also spent literally days googling around for anything
like this but so far all has been in vain. Then again, this exceeds my
expertise on application servers and locking/transactions.
The hosting provider claims that there is no stateful component between
the hosts that would drop a connection it assumes dead. The AS is on a
virtualised Windows Server 2008 hosted in a VMWare ESX5i cluster, also the
proxy is hosted there. Oracle RAC (on "real" HW) is physically within the
same server room and within the same subnet.
I've inspected the network connections during a quiet time early in the
morning. Even though Tomcat status page on JBoss shows a number of long
living connections (which have very little traffic) which more or less
coincides with the number of open DB connections, looking at the output of
netstat -no on the JBoss server showed only one connection between Apache
and JBoss. The open DB connections did show in netstat output. Looking at
the netstat -no output on Apache server showed large number of connections
to JBoss in TIME_WAIT and plenty of client connections in FIN_WAIT2.
The fact that there is a thread waiting for a lock to be released by
another thread makes me wonder if there is a bug in JTA but at least it is
a rare bug and seems oddly to interfere with only transactions of one
kind. OTOH I'm not sure which way the TCP connections point at, and
communication with the staff of the application supplier hasn't so far
provided any solution. I've also experimented with timeout and keepalive
settings on both Apache and JBoss AJP connections without any change in
the situation. Also the fact that the open DB connections are toward the
object persistence DB (xa-datasource) and not toward the message
persistence DB (local-tx-datasource) is a bit confusing as there are those
messages in delivering state...
Any thoughts, pointers, ideas, or topics for further research?