Return-Path: Delivered-To: apmail-ibatis-user-java-archive@www.apache.org Received: (qmail 96418 invoked from network); 13 Sep 2007 13:59:23 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 13 Sep 2007 13:59:23 -0000 Received: (qmail 37932 invoked by uid 500); 13 Sep 2007 13:59:15 -0000 Delivered-To: apmail-ibatis-user-java-archive@ibatis.apache.org Received: (qmail 37429 invoked by uid 500); 13 Sep 2007 13:59:14 -0000 Mailing-List: contact user-java-help@ibatis.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user-java@ibatis.apache.org Delivered-To: mailing list user-java@ibatis.apache.org Received: (qmail 37418 invoked by uid 99); 13 Sep 2007 13:59:14 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 13 Sep 2007 06:59:14 -0700 X-ASF-Spam-Status: No, hits=3.8 required=10.0 tests=HTML_MESSAGE,MIME_QP_LONG_LINE,MISSING_MIMEOLE,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: local policy) Received: from [195.167.165.141] (HELO trisystems.co.uk) (195.167.165.141) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 13 Sep 2007 14:00:51 +0000 Received: by trisystems.co.uk (CommuniGate Pro PIPE 5.1.3) with PIPE id 963602; Thu, 13 Sep 2007 14:58:48 +0100 Received: from [192.168.1.101] (account tannison@trisystems.co.uk) by trisystems.co.uk (CommuniGate Pro IMAP 5.1.3) with XMIT id 963598 for user-java@ibatis.apache.org; Thu, 13 Sep 2007 14:58:40 +0100 Subject: Spring, Ibatis, and DBCP commons pooling Date: Thu, 13 Sep 2007 14:58:01 +0100 Organization: TriSystems Ltd. Message-Id: <1175df97f0e85943ab13d04aeeb71bd2@elvis> X-ProcessedID: 1175df97f0e85943ab13d04aeeb71bd2@elvis MIME-Version: 1.0 Thread-Topic: Spring, Ibatis, and DBCP commons pooling Priority: Normal Importance: normal X-MSMail-Priority: normal X-Priority: 3 Sensitivity: Normal Thread-Index: Acf2DhlEmbpLV4eXStKtaLxCuQJAgQ== From: "Tracey Annison" To: "user-java@ibatis.apache.org" X-MAPI-LastModified: Thu, 13 Sep 2007 14:58:01 +0100 X-Mailer: CommuniGate Pro MAPI Connector 1.2.5/1.2.9 Content-Type: multipart/alternative; boundary="----_=_NextPart_14771_00021726.00005447" X-Virus-Checked: Checked by ClamAV on apache.org ------_=_NextPart_14771_00021726.00005447 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable We are using Java with Spring to access AS/400 databases via Ibatis and the SQLMapClient, and pooling connections via the Apache Commons DBCP. We have a problem when the application remains running, but the AS/400 connection is lost, due to a closed job or an IPL or whatever. After this happens, the first call on the database fails, though subsequent calls succeed. The odd thing is that it seems to be failing while trying to return the bad connection, presumably as part of some cleanup operation, which would hopefully be followed by an attempt to reconnect? It looks to me as though the Spring DataSourceUtils finds that the connection is dead, and tries to return it to the pool (presumably prior to obtaining a less dead one?) and clashes with the Tomcat DBCP that has already done so. But I cannot seem to find a way of seeing what is going on during this process, as I can't find out how to log these actions in any more detail. So I don't know how to correct this issue... can anyone help me? We are setting up an Ibatis DataSource in Spring like this : [CODE] java:comp/env/jdbc/host /WEB-INF/sql-map-config.xml true [/CODE] Which uses the following settings in the Ibatis sql-map-client.xml : [CODE] [/CODE] And also these Apache DBCP settings in context.xml : [CODE] factory org.apache.commons.dbcp.BasicDataSourceFactory maxActive 10 maxIdle 2 maxWait 100 testOnBorrow true validationQuery select 1 [/CODE] Using these log4J settings to get the debugs : [CODE]log4j.category.com.ibatis =3D DEBUG, file log4j.category.org.apache =3D DEBUG, file log4j.category.org.springframework =3D DEBUG, file[/CODE] We see logging like this for a successful result, AS/400 present, all is well : [CODE]11:43:45,271 uk.co.XXX.our.soap.OurService.getItem():359 - Using sqlMapClient >com.ibatis.sqlmap.engine.impl.SqlMapClientImpl@1705cd8< 11:43:45,271 uk.co.XXX.our.soap.OurService.getItem():361 - sqlMapClient.getCurrentConnection() is >null< 11:43:45,271 uk.co.XXX.our.soap.OurService.getItem():363 - sqlMapClient.getDataSource() is >org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy@1df 9efc< 11:43:45,287 org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection():11 1 - Fetching JDBC Connection from DataSource 11:43:52,803 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {conn-100000} Connection 11:43:53,365 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {pstm-100001} PreparedStatement: select count(*) from etc, etc, etc.... 11:43:53,365 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {pstm-100001} Parameters: [etc, etc] 11:43:53,365 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {pstm-100001} Types: [etc, etc] 11:43:54,850 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {rset-100002} ResultSet 11:43:54,881 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {rset-100002} Header: [00001] 11:43:54,881 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {rset-100002} Result: [1] 11:43:54,975 org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection( ):285 - Returning JDBC Connection to DataSource [/CODE] And logging like this for an unsuccessful result, when the AS/400 job has been closed in the meantime : [CODE]11:51:05,537 uk.co.XXX.our.soap.OurService.getItem():359 - Using sqlMapClient >com.ibatis.sqlmap.engine.impl.SqlMapClientImpl@1705cd8< 11:51:05,537 uk.co.XXX.our.soap.OurService.getItem():361 - sqlMapClient.getCurrentConnection() is >null< 11:51:05,537 uk.co.XXX.our.soap.OurService.getItem():363 - sqlMapClient.getDataSource() is >org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy@1df 9efc< 11:51:05,537 org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection():11 1 - Fetching JDBC Connection from DataSource 11:51:05,537 com.ibatis.common.logging.jakarta.JakartaCommonsLoggingImpl.debug():23 - {conn-100064} Connection 11:51:05,553 org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection( ):285 - Returning JDBC Connection to DataSource 11:51:05,615 uk.co.XXX.our.dao.OurIbatisDAO.isItemExtant():538 - Ibatis DAO Exception java.sql.SQLException: Already closed. at org.apache.tomcat.dbcp.dbcp.PoolableConnection.close(PoolableConnection. java:77) at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper .close(PoolingDataSource.java:180) at org.springframework.jdbc.datasource.DataSourceUtils.doReleaseConnection( DataSourceUtils.java:286) at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$Tran sactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.jav a:161) at $Proxy52.close(Unknown Source) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at com.ibatis.common.jdbc.logging.ConnectionLogProxy.invoke(ConnectionLogPr oxy.java:62) at $Proxy50.close(Unknown Source) at com.ibatis.sqlmap.engine.transaction.external.ExternalTransaction.close( ExternalTransaction.java:82) at com.ibatis.sqlmap.engine.transaction.TransactionManager.end(TransactionM anager.java:110) at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.endTransaction(SqlM apExecutorDelegate.java:776) at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.endTransaction(SqlMapSes sionImpl.java:137) at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.endTransaction(SqlMapClie ntImpl.java:115) at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.autoEndTransaction( SqlMapExecutorDelegate.java:860) at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlM apExecutorDelegate.java:568) at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForObject(SqlM apExecutorDelegate.java:536) at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForObject(SqlMapSes sionImpl.java:93) at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.queryForObject(SqlMapClie ntImpl.java:70) at uk.co.XXX.our.dao.OurIbatisDAO.isItemExtant(ItemIbatisDAO.java:528) at uk.co.XXX.our.soap.OurService.getItem(OurService.java:367) at uk.co.XXX.our.soap.OurService.getItem(OurService.java:261) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java :397) at etc, etc, etc.... at java.lang.Thread.run(Unknown Source)[/CODE] Cheers Tracey Annison ---------------------------------------------------------------------- The information in this email is confidential and may be legally privileged. It is intended solely for the addressee. Access to this email by anyone else is unauthorised. If you are not the intended recipient, any disclosure, copying, distribution, or any action taken or omitted to be taken in reliance on it, is prohibited and may be unlawful. TriSystems Ltd. cannot accept liability for statements made which are clearly the sender's own. ------_=_NextPart_14771_00021726.00005447 Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable

We are using Java with Spring to access AS= /400 databases via Ibatis and the SQLMapClient, and pooling connections via= the Apache Commons DBCP. We have a problem when the application remains ru= nning, but the AS/400 connection is lost, due to a closed job or an IPL or = whatever. After this happens, the first call on the database fails, though = subsequent calls succeed.

The odd thing is that it seems to be faili= ng while trying to return the bad connection, presumably as part of some cl= eanup operation, which would hopefully be followed by an attempt to reconne= ct? It looks to me as though the Spring DataSourceUtils finds that the conn= ection is dead, and tries to return it to the pool (presumably prior to obt= aining a less dead one?) and clashes with the Tomcat DBCP that has already = done so. But I cannot seem to find a way of seeing what is going on during = this process, as I can't find out how to log these actions in any more deta= il.

So I don’t know how to correct this = issue... can anyone help me?
We are setting up an Ibatis DataSource in= Spring like this :
[CODE]<bean id=3D"iseriesJdbcDataSour= ce" class=3D"org.springframework.jndi.JndiObjectFactoryBean"= >
<property name=3D"jndiName&quo= t;>
<value>java:comp/env/jdbc/host&l= t;/value>
</property>
</bean>
<bean id=3D"sqlMapClient" cl= ass=3D"org.springframework.orm.ibatis.SqlMapClientFactoryBean">= ;
<property name=3D"configLocati= on">
<value>/WEB-INF/sql-map-config.x= ml</value>
</property>
<property name=3D"useTransacti= onAwareDataSource">
<value>true</value>=
</property>
<property name=3D"dataSource&q= uot;>
<ref bean=3D"iseriesJdbcDataSo= urce"/>
</property>
</bean>
<bean id=3D"sqlMapClientTemplate&= quot; class=3D"org.springframework.orm.ibatis.SqlMapClientTemplate&quo= t;>
<property name=3D"sqlMapClient= ">
<ref bean=3D"sqlMapClient"= ;/>
</property>
</bean>
<bean id=3D"ourDAO" class=3D= "uk.co.XXX.our.dao.OurIbatisDAO">
<property name=3D"sqlMapClient= Template">
<ref bean=3D"sqlMapClientTempl= ate"/>
</property>
</bean>[/CODE]
Which uses the following settings in the = Ibatis sql-map-client.xml :
[CODE] <transactionManager type=3D"JD= BC">
<dataSource type=3D"JNDI"= >
<property name=3D"DataSource&q= uot; value=3D"java:comp/env/jdbc/host" />
</dataSource>
</transactionManager>[/CODE]
And also these Apache DBCP settings in co= ntext.xml :
[CODE]<Resource name=3D"jdbc/host&quo= t;
auth=3D"Container"
type=3D"javax.sql.DataSource"= ;
driverClassName=3D"com.ibm.as400.= access.AS400JDBCDriver"
url=3D"jdbc:as400://999.999.999.9= 99/HOSTLIB;prompt=3Dfalse;naming=3Dsystem;dateformat=3Diso"
username=3D"HOSTUSER"=
password=3D"HOSTPWD" />
<ResourceParams name=3D"jdbc/host= ">
<parameter>
<name>factory</name>
<value>org.apache.commons.dbcp.B= asicDataSourceFactory</value> </parameter>
<parameter>
<name>maxActive</name>
<value>10</value>
</parameter>
<parameter>
<name>maxIdle</name>
<value>2</value>
</parameter>
<parameter>
<name>maxWait</name>
<value>100</value><= FONT FACE=3D"Times New Roman">
</parameter>
<parameter>
<name>testOnBorrow</name><= /FONT>
<value>true</value>=
</parameter>
<parameter>
<name>validationQuery</name&g= t;
<value>select 1</value>
</parameter>
</ResourceParams>[/CODE]<= FONT FACE=3D"Times New Roman">

Using these log4J settings to get the deb= ugs :
[CODE]log4j.category.com.ibatis =3D DEBUG, fi= le
log4j.category.org.apache =3D DEBUG, f= ile
log4j.category.org.springframework =3D= DEBUG, file[/CODE]
We see logging like this for a successful= result, AS/400 present, all is well :
[CODE]11:43:45,271 uk.co.XXX.our.soap.= OurService.getItem():359 - Using sqlMapClient >com.ibatis.sqlmap.engine.= impl.SqlMapClientImpl@1705cd8<

11:43:45,271 uk.co.XXX.our.soap.OurService= .getItem():361 - sqlMapClient.getCurrentConnection() is >null<=
11:43:45,271 uk.co.XXX.our.soap.OurSer= vice.getItem():363 - sqlMapClient.getDataSource() is >org.springframewor= k.jdbc.datasource.TransactionAwareDataSourceProxy@1df9efc<

11:43:45,287 org.springframework.jdbc.data= source.DataSourceUtils.doGetConnection():111 - Fetching JDBC Connection fro= m DataSource

11:43:52,803 com.ibatis.common.logging.jak= arta.JakartaCommonsLoggingImpl.debug():23 - {conn-100000} Connection=
11:43:53,365 com.ibatis.common.logging= .jakarta.JakartaCommonsLoggingImpl.debug():23 - {pstm-100001} PreparedState= ment: select count(*) from etc, etc, etc....

11:43:53,365 com.ibatis.common.logging.jak= arta.JakartaCommonsLoggingImpl.debug():23 - {pstm-100001} Parameters: [etc,= etc]

11:43:53,365 com.ibatis.common.logging.jak= arta.JakartaCommonsLoggingImpl.debug():23 - {pstm-100001} Types: [etc, etc]=
11:43:54,850 com.ibatis.common.logging= .jakarta.JakartaCommonsLoggingImpl.debug():23 - {rset-100002} ResultSet
11:43:54,881 com.ibatis.common.logging= .jakarta.JakartaCommonsLoggingImpl.debug():23 - {rset-100002} Header: [0000= 1]
11:43:54,881 com.ibatis.common.logging= .jakarta.JakartaCommonsLoggingImpl.debug():23 - {rset-100002} Result: [1]
11:43:54,975 org.springframework.jdbc.= datasource.DataSourceUtils.doReleaseConnection():285 - Returning JDBC Conne= ction to DataSource

[/CODE]
And logging like this for an unsuccessful= result, when the AS/400 job has been closed in the meantime :
[CODE]11:51:05,537 uk.co.XXX.our.soap.OurServ= ice.getItem():359 - Using sqlMapClient >com.ibatis.sqlmap.engine.impl.Sq= lMapClientImpl@1705cd8<

11:51:05,537 uk.co.XXX.our.soap.OurService= .getItem():361 - sqlMapClient.getCurrentConnection() is >null<=
11:51:05,537 uk.co.XXX.our.soap.OurSer= vice.getItem():363 - sqlMapClient.getDataSource() is >org.springframewor= k.jdbc.datasource.TransactionAwareDataSourceProxy@1df9efc<

11:51:05,537 org.springframework.jdbc.data= source.DataSourceUtils.doGetConnection():111 - Fetching JDBC Connection fro= m DataSource

11:51:05,537 com.ibatis.common.logging.jak= arta.JakartaCommonsLoggingImpl.debug():23 - {conn-100064} Connection=
11:51:05,553 org.springframework.jdbc.= datasource.DataSourceUtils.doReleaseConnection():285 - Returning JDBC Conne= ction to DataSource

11:51:05,615 uk.co.XXX.our.dao.OurIbatisDA= O.isItemExtant():538 - Ibatis DAO Exception
java.sql.SQLException: Already closed.=
at org.apache.tomcat.dbcp.dbcp.Poolabl= eConnection.close(PoolableConnection.java:77)
at org.apache.tomcat.dbcp.dbcp.Pooling= DataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:180)
at org.springframework.jdbc.datasource= .DataSourceUtils.doReleaseConnection(DataSourceUtils.java:286)
at org.springframework.jdbc.datasource= .TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(T= ransactionAwareDataSourceProxy.java:161)

at $Proxy52.close(Unknown Source)
at sun.reflect.NativeMethodAccessorImp= l.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImp= l.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccesso= rImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unk= nown Source)
at com.ibatis.common.jdbc.logging.Conn= ectionLogProxy.invoke(ConnectionLogProxy.java:62)
at $Proxy50.close(Unknown Source)
at com.ibatis.sqlmap.engine.transactio= n.external.ExternalTransaction.close(ExternalTransaction.java:82)
at com.ibatis.sqlmap.engine.transactio= n.TransactionManager.end(TransactionManager.java:110)
at com.ibatis.sqlmap.engine.impl.SqlMa= pExecutorDelegate.endTransaction(SqlMapExecutorDelegate.java:776)
at com.ibatis.sqlmap.engine.impl.SqlMa= pSessionImpl.endTransaction(SqlMapSessionImpl.java:137)
at com.ibatis.sqlmap.engine.impl.SqlMa= pClientImpl.endTransaction(SqlMapClientImpl.java:115)
at com.ibatis.sqlmap.engine.impl.SqlMa= pExecutorDelegate.autoEndTransaction(SqlMapExecutorDelegate.java:860)
at com.ibatis.sqlmap.engine.impl.SqlMa= pExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:568)
at com.ibatis.sqlmap.engine.impl.SqlMa= pExecutorDelegate.queryForObject(SqlMapExecutorDelegate.java:536)
at com.ibatis.sqlmap.engine.impl.SqlMa= pSessionImpl.queryForObject(SqlMapSessionImpl.java:93)
at com.ibatis.sqlmap.engine.impl.SqlMa= pClientImpl.queryForObject(SqlMapClientImpl.java:70)
at uk.co.XXX.our.dao.OurIbatisDAO.isIt= emExtant(ItemIbatisDAO.java:528)
at uk.co.XXX.our.soap.OurService.getIt= em(OurService.java:367)
at uk.co.XXX.our.soap.OurService.getIt= em(OurService.java:261)
at sun.reflect.NativeMethodAccessorImp= l.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImp= l.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccesso= rImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unk= nown Source)
at org.apache.axis.providers.java.RPCP= rovider.invokeMethod(RPCProvider.java:397)
at etc, etc, etc....
at java.lang.Thread.run(Unknown Source)[/= CODE]


Cheers
Tracey Annison

----------------------------------------------------------------------
The information in this email is confidential and may be legally privileged.
It is intended solely for the addressee. Access to this email by
anyone else is unauthorised. If you are not the intended recipient,
any disclosure, copying, distribution, or any action taken or omitted
to be taken in reliance on it, is prohibited and may be unlawful.
TriSystems Ltd. cannot accept liability for statements made which are clearly
the sender's own.
------_=_NextPart_14771_00021726.00005447--