we have troubles with not closed connections to DB in our application. I was trying everything, so I got to experimenting with DBCP.
Here are steps to reproduce problem:
1) I've installed on Windows:
- clean apache-tomcat-7.0.59
- Java 1.7.0_75
2) I've changed server.xml, I've added one Resource pointing to our DB
<Resource auth="Container"
defaultTransactionIsolation="READ_COMMITTED"
driverClassName="oracle.jdbc.OracleDriver"
maxActive="20"
initialSize="2"
maxIdle="10"
minIdle="2"
maxWait="10000"
timeBetweenEvictionRunsMillis="60000"
minEvictableIdleTimeMillis="60000"
testOnBorrow="true"
validationInterval="30000"
removeAbandoned="true"
removeAbandonedTimeout="60"
logAbandoned="true"
name="docpilotDB"
password="xxx"
type="javax.sql.DataSource"
url="jdbc:oracle:thin:@1.1.1.1:1521:xe"
username="zzz"
validationQuery="SELECT 1 FROM DUAL"/>
3) I've added ojdbc6_g.jar to tomcat/lib directory
4) Then, I've created and deploy application with
<Context path="/drm">
<ResourceLink global="docpilotDB" name="jdbc/docpilotDB" type="javax.sql.DataSource"/>
</Context>
and with one one test servlet
<servlet>
<servlet-name>Initial Service</servlet-name>
<servlet-class>net.docucom.csas.oms.drm_x.srvlt.InitialService</servlet-class>
<load-on-startup>1</load-on-startup>
</servlet>
And the Servlet class is
public class InitialService extends GenericServlet {
private static final Logger log = LoggerFactory.getLogger(InitialService.class);
private DataSource ds;
public void init(ServletConfig config) throws ServletException {
super.init(config);
try {
ds = getDataSource();
run();
} catch (Exception e) {
throw new ServletException(e);
}
}
private DataSource getDataSource() throws SQLException {
try {
InitialContext ic = new InitialContext();
DataSource ds = (DataSource) ic.lookup("java:comp/env/jdbc/docpilotDB");
return ds;
} catch (NamingException e) {
throw new RuntimeException("Unable to get DataSource", e);
}
}
public void service(ServletRequest arg0, ServletResponse arg1) throws ServletException, IOException {
}
private synchronized void run() throws Exception {
log.info("InitialService: start");
for (int i = 0; i < 100; i++) {
log.info("InitialService: counter=" + i);
Thread.sleep(100);
doSelect();
}
log.info("InitialService: end");
}
synchronized public Connection connect() throws Exception {
int result = -1;
log.debug("connect(): start");
Connection con = null;
try {
con = ds.getConnection();
log.debug("connect(): got connection " + con.getClass().getName());
log.debug("connect(): " + DriverManager.getDriver(ds.getConnection().getMetaData().getURL()).getClass());
result = 0;
} catch (Throwable e) {
log.error("connect() Error!", e);
con = null;
return con;
}
log.debug("connect(): result=" + result);
return con;
}
synchronized public int close(Connection con) throws Exception {
int result = -1;
log.debug("close(): start");
if (con != null) {
log.debug("con.close();");
con.close();
log.debug("con.isClosed=" + con.isClosed());
con = null;
}
result = 0;
log.debug("close(): result=" + result);
return result;
}
public synchronized void doSelect() throws Exception {
log.debug("doSelect(): start");
Connection con = null;
//ResultSet res = null;
try{
con = connect();
// if (stmt == null) {
// stmt = con.createStatement();
// }
//
// res = this.stmt.executeQuery("SELECT * FROM [DRM_OMS].[dbo].[Vat]");
// while (res.next()) {
// String Id = res.getString("id");
// String DPH = res.getString("DPH");
//
// }
//
// res.close();
// res = null;
} finally {
if (con != null){
close(con);
}
}
log.debug("doSelect(): end");
}
}
There is no other customization on the tomcat server.
The log looks pritty nice until the 20.iteration
11:12:58.850 INFO InitialService: start
11:12:58.856 INFO InitialService: counter=0
11:12:58.957 DEBUG doSelect(): start
11:12:58.957 DEBUG connect(): start
11:12:59.056 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:12:59.079 DEBUG connect(): class oracle.jdbc.OracleDriver
11:12:59.079 DEBUG connect(): result=0
11:12:59.079 DEBUG close(): start
11:12:59.079 DEBUG con.close();
11:12:59.079 DEBUG con.isClosed=true
11:12:59.079 DEBUG close(): result=0
11:12:59.080 DEBUG doSelect(): end
11:12:59.080 INFO InitialService: counter=1
11:12:59.180 DEBUG doSelect(): start
11:12:59.180 DEBUG connect(): start
11:12:59.205 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:12:59.761 DEBUG connect(): class oracle.jdbc.OracleDriver
11:12:59.761 DEBUG connect(): result=0
11:12:59.762 DEBUG close(): start
11:12:59.762 DEBUG con.close();
11:12:59.762 DEBUG con.isClosed=true
11:12:59.762 DEBUG close(): result=0
11:12:59.762 DEBUG doSelect(): end
11:12:59.762 INFO InitialService: counter=2
11:12:59.863 DEBUG doSelect(): start
11:12:59.863 DEBUG connect(): start
11:12:59.884 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:00.524 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:00.524 DEBUG connect(): result=0
11:13:00.524 DEBUG close(): start
11:13:00.524 DEBUG con.close();
11:13:00.524 DEBUG con.isClosed=true
11:13:00.524 DEBUG close(): result=0
11:13:00.524 DEBUG doSelect(): end
11:13:00.524 INFO InitialService: counter=3
11:13:00.624 DEBUG doSelect(): start
11:13:00.624 DEBUG connect(): start
11:13:00.679 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:01.315 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:01.315 DEBUG connect(): result=0
11:13:01.315 DEBUG close(): start
11:13:01.316 DEBUG con.close();
11:13:01.316 DEBUG con.isClosed=true
11:13:01.316 DEBUG close(): result=0
11:13:01.316 DEBUG doSelect(): end
11:13:01.316 INFO InitialService: counter=4
11:13:01.416 DEBUG doSelect(): start
11:13:01.416 DEBUG connect(): start
11:13:01.462 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:02.146 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:02.146 DEBUG connect(): result=0
11:13:02.146 DEBUG close(): start
11:13:02.146 DEBUG con.close();
11:13:02.146 DEBUG con.isClosed=true
11:13:02.146 DEBUG close(): result=0
11:13:02.146 DEBUG doSelect(): end
11:13:02.147 INFO InitialService: counter=5
11:13:02.247 DEBUG doSelect(): start
11:13:02.247 DEBUG connect(): start
11:13:02.289 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:02.984 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:02.984 DEBUG connect(): result=0
11:13:02.984 DEBUG close(): start
11:13:02.984 DEBUG con.close();
11:13:02.984 DEBUG con.isClosed=true
11:13:02.984 DEBUG close(): result=0
11:13:02.984 DEBUG doSelect(): end
11:13:02.984 INFO InitialService: counter=6
11:13:03.084 DEBUG doSelect(): start
11:13:03.084 DEBUG connect(): start
11:13:03.118 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:03.447 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:03.447 DEBUG connect(): result=0
11:13:03.447 DEBUG close(): start
11:13:03.447 DEBUG con.close();
11:13:03.447 DEBUG con.isClosed=true
11:13:03.447 DEBUG close(): result=0
11:13:03.447 DEBUG doSelect(): end
11:13:03.447 INFO InitialService: counter=7
11:13:03.547 DEBUG doSelect(): start
11:13:03.547 DEBUG connect(): start
11:13:03.566 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:03.804 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:03.804 DEBUG connect(): result=0
11:13:03.804 DEBUG close(): start
11:13:03.804 DEBUG con.close();
11:13:03.804 DEBUG con.isClosed=true
11:13:03.804 DEBUG close(): result=0
11:13:03.805 DEBUG doSelect(): end
11:13:03.805 INFO InitialService: counter=8
11:13:03.906 DEBUG doSelect(): start
11:13:03.906 DEBUG connect(): start
11:13:03.927 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:04.163 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:04.164 DEBUG connect(): result=0
11:13:04.164 DEBUG close(): start
11:13:04.164 DEBUG con.close();
11:13:04.164 DEBUG con.isClosed=true
11:13:04.164 DEBUG close(): result=0
11:13:04.164 DEBUG doSelect(): end
11:13:04.164 INFO InitialService: counter=9
11:13:04.265 DEBUG doSelect(): start
11:13:04.265 DEBUG connect(): start
11:13:04.282 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:04.517 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:04.518 DEBUG connect(): result=0
11:13:04.518 DEBUG close(): start
11:13:04.518 DEBUG con.close();
11:13:04.518 DEBUG con.isClosed=true
11:13:04.518 DEBUG close(): result=0
11:13:04.518 DEBUG doSelect(): end
11:13:04.518 INFO InitialService: counter=10
11:13:04.618 DEBUG doSelect(): start
11:13:04.618 DEBUG connect(): start
11:13:04.643 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:04.876 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:04.876 DEBUG connect(): result=0
11:13:04.876 DEBUG close(): start
11:13:04.876 DEBUG con.close();
11:13:04.876 DEBUG con.isClosed=true
11:13:04.876 DEBUG close(): result=0
11:13:04.876 DEBUG doSelect(): end
11:13:04.876 INFO InitialService: counter=11
11:13:04.977 DEBUG doSelect(): start
11:13:04.977 DEBUG connect(): start
11:13:04.993 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:05.246 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:05.246 DEBUG connect(): result=0
11:13:05.247 DEBUG close(): start
11:13:05.247 DEBUG con.close();
11:13:05.247 DEBUG con.isClosed=true
11:13:05.247 DEBUG close(): result=0
11:13:05.247 DEBUG doSelect(): end
11:13:05.247 INFO InitialService: counter=12
11:13:05.348 DEBUG doSelect(): start
11:13:05.348 DEBUG connect(): start
11:13:05.371 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:05.639 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:05.639 DEBUG connect(): result=0
11:13:05.640 DEBUG close(): start
11:13:05.640 DEBUG con.close();
11:13:05.640 DEBUG con.isClosed=true
11:13:05.640 DEBUG close(): result=0
11:13:05.640 DEBUG doSelect(): end
11:13:05.640 INFO InitialService: counter=13
11:13:05.740 DEBUG doSelect(): start
11:13:05.740 DEBUG connect(): start
11:13:05.760 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:06.002 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:06.003 DEBUG connect(): result=0
11:13:06.003 DEBUG close(): start
11:13:06.003 DEBUG con.close();
11:13:06.003 DEBUG con.isClosed=true
11:13:06.003 DEBUG close(): result=0
11:13:06.003 DEBUG doSelect(): end
11:13:06.003 INFO InitialService: counter=14
11:13:06.105 DEBUG doSelect(): start
11:13:06.105 DEBUG connect(): start
11:13:06.121 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:06.348 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:06.348 DEBUG connect(): result=0
11:13:06.348 DEBUG close(): start
11:13:06.348 DEBUG con.close();
11:13:06.348 DEBUG con.isClosed=true
11:13:06.348 DEBUG close(): result=0
11:13:06.348 DEBUG doSelect(): end
11:13:06.348 INFO InitialService: counter=15
11:13:06.448 DEBUG doSelect(): start
11:13:06.448 DEBUG connect(): start
11:13:06.467 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:06.747 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:06.747 DEBUG connect(): result=0
11:13:06.747 DEBUG close(): start
11:13:06.747 DEBUG con.close();
11:13:06.747 DEBUG con.isClosed=true
11:13:06.747 DEBUG close(): result=0
11:13:06.747 DEBUG doSelect(): end
11:13:06.747 INFO InitialService: counter=16
11:13:06.848 DEBUG doSelect(): start
11:13:06.848 DEBUG connect(): start
11:13:06.862 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:07.112 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:07.112 DEBUG connect(): result=0
11:13:07.112 DEBUG close(): start
11:13:07.112 DEBUG con.close();
11:13:07.112 DEBUG con.isClosed=true
11:13:07.112 DEBUG close(): result=0
11:13:07.112 DEBUG doSelect(): end
11:13:07.112 INFO InitialService: counter=17
11:13:07.214 DEBUG doSelect(): start
11:13:07.214 DEBUG connect(): start
11:13:07.233 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:07.477 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:07.479 DEBUG connect(): result=0
11:13:07.479 DEBUG close(): start
11:13:07.479 DEBUG con.close();
11:13:07.479 DEBUG con.isClosed=true
11:13:07.479 DEBUG close(): result=0
11:13:07.480 DEBUG doSelect(): end
11:13:07.480 INFO InitialService: counter=18
11:13:07.580 DEBUG doSelect(): start
11:13:07.580 DEBUG connect(): start
11:13:07.603 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:07.866 DEBUG connect(): class oracle.jdbc.OracleDriver
11:13:07.867 DEBUG connect(): result=0
11:13:07.867 DEBUG close(): start
11:13:07.867 DEBUG con.close();
11:13:07.867 DEBUG con.isClosed=true
11:13:07.867 DEBUG close(): result=0
11:13:07.867 DEBUG doSelect(): end
11:13:07.867 INFO InitialService: counter=19
11:13:07.968 DEBUG doSelect(): start
11:13:07.968 DEBUG connect(): start
11:13:07.991 DEBUG connect(): got connection org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper
11:13:18.001 ERROR connect() Error!
java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1171) ~[tomcat-dbcp.jar:7.0.59]
at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:79) ~[tomcat-dbcp.jar:7.0.59]
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) ~[tomcat-dbcp.jar:7.0.59]
... 21 common frames omitted
Wrapped by: org.apache.tomcat.dbcp.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114) ~[tomcat-dbcp.jar:7.0.59]
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044) ~[tomcat-dbcp.jar:7.0.59]
at net.docucom.csas.oms.drm_x.srvlt.InitialService.connect(InitialService.java:68) [InitialService.class:na]
at net.docucom.csas.oms.drm_x.srvlt.InitialService.doSelect(InitialService.java:99) [InitialService.class:na]
at net.docucom.csas.oms.drm_x.srvlt.InitialService.run(InitialService.java:54) [InitialService.class:na]
at net.docucom.csas.oms.drm_x.srvlt.InitialService.init(InitialService.java:30) [InitialService.class:na]
at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1284) [catalina.jar:7.0.59]
at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1197) [catalina.jar:7.0.59]
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1087) [catalina.jar:7.0.59]
at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5262) [catalina.jar:7.0.59]
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5550) [catalina.jar:7.0.59]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [catalina.jar:7.0.59]
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901) [catalina.jar:7.0.59]
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877) [catalina.jar:7.0.59]
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:649) [catalina.jar:7.0.59]
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1081) [catalina.jar:7.0.59]
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1877) [catalina.jar:7.0.59]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75]
at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_75]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_75]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
11:13:18.001 DEBUG doSelect(): end
11:13:18.001 INFO InitialService: counter=20
11:13:18.102 DEBUG doSelect(): start
11:13:18.102 DEBUG connect(): start
and after abandoned timeout the console of tomcat is full of messages that DBCP is not closed.
org.apache.tomcat.dbcp.dbcp.AbandonedTrace$AbandonedObjectException: DBCP object created 2016-02-05 11:12:59 by the following code was never closed:
at org.apache.tomcat.dbcp.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java:139)
at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:81)
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
at net.docucom.csas.oms.drm_x.srvlt.InitialService.connect(InitialService.java:68)
at net.docucom.csas.oms.drm_x.srvlt.InitialService.doSelect(InitialService.java:99)
at net.docucom.csas.oms.drm_x.srvlt.InitialService.run(InitialService.java:54)
at net.docucom.csas.oms.drm_x.srvlt.InitialService.init(InitialService.java:30)
at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1284)
at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1197)
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1087)
at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5262)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5550)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:649)
at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1081)
at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1877)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
org.apache.tomcat.dbcp.dbcp.AbandonedTrace$AbandonedObjectException: DBCP object created 2016-02-05 11:12:59 by the following code was never closed:
at org.apache.tomcat.dbcp.dbcp.AbandonedTrace.init(AbandonedTrace.java:90)
at org.apache.tomcat.dbcp.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:73)
at org.apache.tomcat.dbcp.dbcp.DelegatingDatabaseMetaData.<init>(DelegatingDatabaseMetaData.java:52)
at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.getMetaData(DelegatingConnection.java:345)
...................
Could someone help with this issue? There is no logic now, I'm only fighting with DBCP and connections via DataSource. I'm pretty sure, that I'm closing connections. It is clear in the Java code.
Why are the connections not closed? Please help!
Kind regards and thank you for your time and help.
Martin M.
The logging is getting an extra connection each time through the loop:
Each time this runs, it gets a connection from the datasource. After 20 iterations, the connection pool has 20 connections "in use". Since
maxActive=20theDataSourcecan't create another connection. Hence the next call fails waiting for one of the 20 unused/unclosed connections to get closed.The later exceptions are complaining about those connections that never got closed.
The logging line should use the connection already retrieved.