Bug 1121935

Summary: Running test-connection-in-pool operation leaves datasource in a bad state
Product: [JBoss] JBoss Enterprise Application Platform 6 Reporter: bkramer <bkramer>
Component: JCAAssignee: Martin Simka <msimka>
Status: CLOSED CURRENTRELEASE QA Contact: Martin Simka <msimka>
Severity: medium Docs Contact: Russell Dickenson <rdickens>
Priority: unspecified    
Version: 6.1.0   
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-09-25 16:21:25 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

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+