Subject Re: [Firebird-Java] reuse of connection after failure.
Author Andrew Goedhart
Here are the configurations JBoss 4.0.5, hibernate 3.2.2, Jaybird 2.1.1, (jdk 5 release 11) SUSE 10 or Ubuntu 6.10 64 bit also tried Jaybird compiled from HEAD.

extract from firebird-ds.xml in jboss deploy directory defining datasource

<tx-connection-factory>
<jndi-name>ModelDS</jndi-name>
<xa-transaction/>
<track-connection-by-tx/>
<rar-name>firebirdsql.rar</rar-name>
<connection-definition>javax.sql.DataSource</connection-definition>
<config-property name="Database" type="java.lang.String">196.37.96.64/3050:model.fdb</config-property>
<user-name>sysdba</user-name>
<password>xxxxxxxxxxx</password>
<config-property name="TransactionIsolationName">TRANSACTION_READ_COMMITTED</config-property>
<config-property name="BlobBufferLength"></config-property>
<min-pool-size>0</min-pool-size>
<new-connection-sql>select RDB$RELATION_ID from RDB$DATABASE</new-connection-sql>
<check-valid-connection-sql>select RDB$RELATION_ID from RDB$DATABASE</check-valid-connection-sql>
<metadata>
<type-mapping>Firebird</type-mapping>
</metadata>
</tx-connection-factory>



we start with one of these:

2007-03-08 23:54:28,379 WARN [org.jboss.tm.TransactionImpl] XAException: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=map01/24854, BranchQual=, localId=24854] errorCode=XA_UNKNOWN(0)
org.firebirdsql.jca.FBXAException
at org.firebirdsql.jca.FBManagedConnection.start(FBManagedConnection.java:973)
at org.jboss.tm.TransactionImpl$Resource.startResource(TransactionImpl.java:2063)
at org.jboss.tm.TransactionImpl.enlistResource(TransactionImpl.java:581)
at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener$TransactionSynchronization.enlist(TxConnectionManager.java:757)
at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.enlist(TxConnectionManager.java:548)
at org.jboss.resource.connectionmanager.TxConnectionManager.managedConnectionReconnected(TxConnectionManager.java:323)
at org.jboss.resource.connectionmanager.BaseConnectionManager2.reconnectManagedConnection(BaseConnectionManager2.java:518)
at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:399)
at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:842)
at org.firebirdsql.jdbc.FBDataSource.getConnection(FBDataSource.java:95)
at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:421)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1538)
at org.hibernate.loader.Loader.doQuery(Loader.java:661)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
at org.hibernate.loader.Loader.loadEntity(Loader.java:1851)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
at org.hibernate.loader.entity.BatchingEntityLoader.load(BatchingEntityLoader.java:82)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3038)
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
at org.hibernate.event.def.DefaultLoadEventListener.lockAndLoad(DefaultLoadEventListener.java:297)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:106)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
at org.hibernate.impl.SessionImpl.load(SessionImpl.java:859)
at org.hibernate.impl.SessionImpl.load(SessionImpl.java:854)
at za.co.duosp.hibernate.timing.SessionProxy.load(SessionProxy.java:201)
at za.co.duosp.msgserver.comms.RxCommsVehicleStatusBean.processMsg(RxCommsVehicleStatusBean.java:50)
at za.co.duosp.msgserver.BaseMsgBean.processMessage(BaseMsgBean.java:136)
at za.co.duosp.jmsserver.MessageBeanCache.processMessage(MessageBeanCache.java:127)
at za.co.duosp.jmsserver.BeanThread.processMsg(BeanThread.java:77)
at za.co.duosp.jmsserver.BeanThread.run(BeanThread.java:48)
at java.lang.Thread.run(Thread.java:595)
2007-03-08 23:54:28,383 WARN [org.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: HY000
2007-03-08 23:54:28,383 ERROR [org.hibernate.util.JDBCExceptionReporter] Problem getting connection: org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=map01/24854, BranchQual=, localId=24854])
2007-03-08 23:54:28,384 INFO [org.hibernate.event.def.DefaultLoadEventListener] Error performing load command
org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:424)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1538)
at org.hibernate.loader.Loader.doQuery(Loader.java:661)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
at org.hibernate.loader.Loader.loadEntity(Loader.java:1851)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
at org.hibernate.loader.entity.BatchingEntityLoader.load(BatchingEntityLoader.java:82)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3038)
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
at org.hibernate.event.def.DefaultLoadEventListener.lockAndLoad(DefaultLoadEventListener.java:297)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:106)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
at org.hibernate.impl.SessionImpl.load(SessionImpl.java:859)
at org.hibernate.impl.SessionImpl.load(SessionImpl.java:854)
at za.co.duosp.hibernate.timing.SessionProxy.load(SessionProxy.java:201)
at za.co.duosp.msgserver.comms.RxCommsVehicleStatusBean.processMsg(RxCommsVehicleStatusBean.java:50)
at za.co.duosp.msgserver.BaseMsgBean.processMessage(BaseMsgBean.java:136)
at za.co.duosp.jmsserver.MessageBeanCache.processMessage(MessageBeanCache.java:127)
at za.co.duosp.jmsserver.BeanThread.processMsg(BeanThread.java:77)
at za.co.duosp.jmsserver.BeanThread.run(BeanThread.java:48)
at java.lang.Thread.run(Thread.java:595)
Caused by: org.firebirdsql.jdbc.FBSQLException: Problem getting connection: org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=map01/24854, BranchQual=, localId=24854])
at org.firebirdsql.jdbc.FBDataSource.getConnection(FBDataSource.java:98)
at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:421)
... 25 more

And then we start to get these:

Caused by: org.firebirdsql.gds.GDSException: cannot disconnect database with open transactions (1 active)
at org.firebirdsql.gds.impl.wire.AbstractJavaGDSImpl.readStatusVector(AbstractJavaGDSImpl.java:2124)
at org.firebirdsql.gds.impl.wire.AbstractJavaGDSImpl.receiveResponse(AbstractJavaGDSImpl.java:2074)
at org.firebirdsql.gds.impl.wire.AbstractJavaGDSImpl.iscDetachDatabase(AbstractJavaGDSImpl.java:621)
at org.firebirdsql.jca.FBManagedConnection.destroy(FBManagedConnection.java:518)
... 13 more
at
org.firebirdsql.gds.GDSException: cannot disconnect database with open transactions (1 active)
at org.firebirdsql.gds.impl.wire.AbstractJavaGDSImpl.readStatusVector(AbstractJavaGDSImpl.java:2124)
at org.firebirdsql.gds.impl.wire.AbstractJavaGDSImpl.receiveResponse(AbstractJavaGDSImpl.java:2074)
at org.firebirdsql.gds.impl.wire.AbstractJavaGDSImpl.iscDetachDatabase(AbstractJavaGDSImpl.java:621)
at org.firebirdsql.jca.FBManagedConnection.destroy(FBManagedConnection.java:518)
at org.firebirdsql.jca.FBManagedConnectionFactory.tryCompleteInLimboTransaction(FBManagedConnectionFactory.java:724)
at org.firebirdsql.jca.FBManagedConnectionFactory.notifyRollback(FBManagedConnectionFactory.java:642)
at org.firebirdsql.jca.FBManagedConnection.rollback(FBManagedConnection.java:896)
at org.jboss.tm.TransactionImpl$Resource.rollback(TransactionImpl.java:2277)
at org.jboss.tm.TransactionImpl.rollbackResources(TransactionImpl.java:1837)
at org.jboss.tm.TransactionImpl.rollback(TransactionImpl.java:412)
at org.jboss.tm.TxManager.rollback(TxManager.java:364)
at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.rollback(ServerVMClientUserTransaction.java:148)
at za.co.duosp.jmsserver.JbossTransaction.end(JbossTransaction.java:75)
at za.co.duosp.jmsserver.BeanThread.processMsg(BeanThread.java:96)
at za.co.duosp.jmsserver.BeanThread.processMsg(BeanThread.java:107)
at za.co.duosp.jmsserver.BeanThread.run(BeanThread.java:48)
at java.lang.Thread.run(Thread.java:595)


Maybe a red herring but we have notices one or two SIGSEV in the fire logs. We are running CS 2.01 RC2 on a separate machine. The problem seems to happen more frequently when we are under heavy load. Approximately 50 000+ transactions (1 000 000+ queries/inserts) per hour. The system may run normally for hours/days and then trigger this on one machine in the cluster. Under heavy load it may trigger in 30 or so minutes. I am guessing when Firebird sigsevs we loose the connection and the connection pool is not recovering properly. After changing the defaults on the connection pool (hard coded see below) so that it tends to throw away connections more often maxIdleTime = 15 and pings connections, we seem to recover easier.

org.firebirdsql.pool.FBPoolingDefaults
public static final int DEFAULT_IDLE_TIMEOUT = 10 * 1000;
public static final int DEFAULT_PING_INTERVAL = 5 * 1000;

org.firebirdsql.pool.BasicAbstractConnectionPool
pingStatement = "SELECT CAST(1 AS INTEGER) FROM RDB$DATABASE";


My real question however is how to get these hard coded defaults into the JBOSS firebird-ds.xml data source configuration file, so that I can use standard releases in the future

Andrew

----- Original Message -----
From: Roman Rokytskyy <rrokytskyy@...>
To: Firebird-Java@yahoogroups.com
Sent: Sunday, March 11, 2007 10:01:08 PM GMT+0200 Africa/Harare
Subject: Re: [Firebird-Java] reuse of connection after failure.






> I have included <check-valid-connection-sql> in my data source definitions but it seems that these are not being applied. I noticed that the connection pool defines pingSql instead.

Please post your configuration here.

> When I have an error on the connection I get a failure on subsequent connections, The stack trace generated for the exception in the Rollback that I do when the subsequent error occurs, states that I cannot close a connection with active connections. Huh?? It looks link the temporary connection generated to deal with the XA semantics is failing and this causes the problem. I am assuming that this temporary connection is taken form the connection pool as well.

Please also post the complete stack trace, so we can see where it happens.

> I have hard coded the new defaults I require for pingsql and idleTime into the connection pool. I am currently testing to see if these solve most of my problems. I would however like to know how to set these( pingSql and idleTime) in the datasource file using xml.

Hmmmm... what connection pool do you use?

> If testing currently proves that the error is due to reusing a connection that has failed. And that the connection is reused by the pool continually even though it fails immediately, should I log this as a bug ?

Let's first check where the problem is, then we will know whether it is
our bug or not.

Roman