Bug 1121935 - Running test-connection-in-pool operation leaves datasource in a bad state
Summary: Running test-connection-in-pool operation leaves datasource in a bad state
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: JCA
Version: 6.1.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: ---
Assignee: Martin Simka
QA Contact: Martin Simka
Russell Dickenson
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-07-22 07:46 UTC by bkramer
Modified: 2018-12-06 17:25 UTC (History)
0 users

Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-09-25 16:21:25 UTC
Type: Bug


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 1137323 None None None Never

Description bkramer 2014-07-22 07:46:35 UTC
Description of problem:
JBoss Operations Network is using test-connection-in-pool operation to test connection to the database. If this is checked frequently (for instance every 5 minutes), after few days, it will not be possible to connect to the database and the only way to fix the problem is to restart the EAP instance or to flush connections in the pool. However, the problem will show up again, after few days.

Version-Release number of selected component (if applicable):
EAP 6.1 - standalone mode

How reproducible:
Always

Steps to Reproduce:
1. Use JBoss ON to monitor datasource
2. Configure JBoss ON to "Test Connection?" every 5 minutes (this is equivalent to:

[standalone@localhost:9999 /] /subsystem=datasources/xa-data-source=testDS/:test-connection-in-pool()

executing every 5 minutes;

3. Leave the system to run like this for next few days;

Actual results:
It is not possible to connect to the database any more and Exceptions similar to the following are logged in the server.log file:
********************************************************
09:21:03,801 ERROR [org.jboss.as.ejb3.invocation] (http-/0.0.0.0:8080-5) JBAS014134: EJB Invocation failed on component TestServiceBean for method public abstract foo.example.Test.beans.FindProfileByPhoneNumberResponse foo.example.Test.TestService.findProfileByPhoneNumber(foo.example.Test.beans.FindProfileByPhoneNumberRequest): javax.ejb.EJBException: java.lang.reflect.UndeclaredThrowableException
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInOurTx(CMTTxInterceptor.java:165) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:250) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:315) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:214) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2]
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2]
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2]
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2]
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2]
	at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8]
[...]
Caused by: java.lang.reflect.UndeclaredThrowableException
	at $Proxy178.findProfileByPhoneNumber(Unknown Source)	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_24]
	...
Caused by: org.switchyard.HandlerException: org.hibernate.exception.GenericJDBCException: Could not open connection
	...
Caused by: org.hibernate.exception.GenericJDBCException: Could not open connection
	...
Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@74e10916[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@628b9bac connection handles=0 lastUse=1404458463799 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2c609822 pool internal context=SemaphoreArrayListManagedConnectionPool@3a80e1ac[pool=TestDS] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@628b9bac txSync=null]
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:147)
	at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:70) [hibernate-entitymanager-4.2.0.Final-redhat-1.jar:4.2.0.Final-redhat-1]
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:292) [hibernate-core-4.2.0.Final-redhat-1.jar:4.2.0.Final-redhat-1]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:214) [hibernate-core-4.2.0.Final-redhat-1.jar:4.2.0.Final-redhat-1]
	... 280 more
Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@74e10916[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@628b9bac connection handles=0 lastUse=1404458463799 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2c609822 pool internal context=SemaphoreArrayListManagedConnectionPool@3a80e1ac[pool=TestDS] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@628b9bac txSync=null]
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:604)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139)
	... 283 more
Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:474)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)
	... 285 more
Caused by: javax.transaction.SystemException: IJ000356: Failed to enlist: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: 0:ffffac19e05b:1c26c48e:53b117f6:993f status: ActionStatus.ABORT_ONLY >
	at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.checkEnlisted(TxConnectionListener.java:572)
	at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:283)
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:467)
	... 286 more
********************************************************


Expected results:
Connection can be opened and no exception is logged in the server.log file.

Additional info:

Comment 1 bkramer 2014-07-22 08:09:01 UTC
As a workaround do one of the following:

  1. Disable the "Test Connection?" trait from JBoss ON;
  2. Restart the EAP server every time the issue happens;
  3. Flush the connections in the pool every time the issue happens.

Comment 2 Martin Simka 2014-09-25 16:21:25 UTC
This issue reported against older version, cannot be reproduced against latest bits (I used 6.4.0.DR2), which means it was fixed earlier. Therefore, we are closing this bug. Thank you for reporting this issue. 

I've tried to run "/subsystem=datasources/xa-data-source=gamificationDS:test-connection-in-pool()" 2000 times with 2 seconds breaks. No error, no exception. 

Datasource used for test:
<xa-datasource jndi-name="java:jboss/datasources/gamificationDS" pool-name="gamificationDS" enabled="true" use-ccm="false">
  <xa-datasource-class>com.mysql.jdbc.jdbc2.optional.MysqlXADataSource</xa-datasource-class>
  <xa-datasource-property name="URL">jdbc:mysql://localhost:3306/test</xa-datasource-property>
  <driver>mysql.jar</driver>
  <xa-pool>
    <is-same-rm-override>false</is-same-rm-override>
    <interleaving>false</interleaving>
    <pad-xid>false</pad-xid>
    <wrap-xa-resource>false</wrap-xa-resource>
  </xa-pool>
  <security>
    <user-name>test</user-name>
    <password>test</password>
  </security>
  <validation>
    <validate-on-match>false</validate-on-match>
    <background-validation>false</background-validation>
  </validation>
  <statement>
    <share-prepared-statements>false</share-prepared-statements>
  </statement>
</xa-datasource>

Feel free to reopen if you experience same problem with JON and EAP 6.3.0+


Note You need to log in before you can comment on or make changes to this bug.