Greetings!
I have a problem, possibly (or not) tied to the Tomcat-JDBC Pool. Here
is the rundown:
Application Server: Apache Tomcat 9.0.56
JDBC Connection Pool: org.apache.tomcat.jdbc.pool.DataSource; Tomcat-JDBC
9.0.56
Oracle Version: Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 -
Production
Java Driver: com.oracle.database.jdbc::ojdbc11 21.4.0.0.1
All of this running on Amazon ECS running between 8 and 20 instances
depending on load
Configuration of Pool:
<Resource name="jdbc/*****"
auth="Container"
type="javax.sql.DataSource"
driverClassName="oracle.jdbc.OracleDriver"
url="**********"
jdbcInterceptors="org.apache.tomcat.jdbc.pool.interceptor.ConnectionState;
org.apache.tomcat.jdbc.pool.interceptor.StatementFinalizer"
factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
username="**********"
password="**********"
validationQuery="SELECT 1 FROM DUAL"
validationInterval="20000"
testWhileIdle="true"
testOnBorrow="true"
testOnReturn="true"
removeAbandoned="true"
removeAbandonedTimeout="300"
logAbandoned="true"
timeBetweenEvictionRunsMillis="30000"
initialSize="50"
minIdle="80"
maxIdle="120"
maxActive="250"
maxWait="-1"/>
Problem:
We are experiencing sporadic spikes where connections are being closed even
though they are in use, or are returned by the connection pool already
closed. This is a high volume API, and it can go days without this
happening and then suddenly it will have a spike out of nowhere.
This does not seem to be tied to any long running activity we can find. I
can see instances where a request got a connection from the pool and it
failed on the first attempt to use just milliseconds after it was returned.
Furthermore it seems to happen randomly in batches where hundreds of these
happen at once on a single JVM, then won't happen again for days.
There are a few different scenarios where we see this, sometimes it occurs
inside of the connection pool, in this case we see a message about not
being able to clear warnings, but not much else. The stack trace gets
truncated after a while but in these cases there is no sub-exception. It's
just the one, this error in the pool propagates up and out and results in a
failed request.
Message: Unable to clear Warnings, connection will be closed.
Logger: org.apache.tomcat.jdbc.pool.PooledConnection
Exception:
java.sql.SQLRecoverableException: Closed Connection
at
oracle.jdbc.driver.PhysicalConnection.requireOpenConnection(PhysicalConnection.java:11773)
at
oracle.jdbc.driver.PhysicalConnection.clearWarnings(PhysicalConnection.java:3526)
at
org.apache.tomcat.jdbc.pool.PooledConnection.clearWarnings(PooledConnection.java:875)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.returnConnection(ConnectionPool.java:1019)
at
org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:103)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:69)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.interceptor.ConnectionState.invoke(ConnectionState.java:158)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at org.apache.tomcat.jdbc.pool.TrapException.invoke(TrapException.java:39)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:69)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy94.close(Unknown Source)
Sometimes we see a similar error AFTER the connection has been returned
from the pool:
message (example, lots of different queries): Resolved
[org.springframework.dao.RecoverableDataAccessException:
PreparedStatementCallback; SQL [******]; Closed Connection; nested
exception is java.sql.SQLRecoverableException: Closed Connection]
exception:
java.sql.SQLRecoverableException: Closed Connection
at
oracle.jdbc.driver.PhysicalConnection.requireOpenConnection(PhysicalConnection.java:11773)
at
oracle.jdbc.driver.PhysicalConnection.prepareStatementInternal(PhysicalConnection.java:2354)
at
oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:2309)
at
oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:2300)
at
oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:2211)
at jdk.internal.reflect.GeneratedMethodAccessor194.invoke(Unknown Source)
at
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:131)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.interceptor.ConnectionState.invoke(ConnectionState.java:158)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at org.apache.tomcat.jdbc.pool.TrapException.invoke(TrapException.java:39)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
at
org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy94.prepareStatement(Unknown Source)
at
org.springframework.jdbc.core.PreparedStatementCreatorFactory$PreparedStatementCreatorImpl.createPreparedStatement(PreparedStatementCreatorFactory.java:235)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:649)
... 155 common frames omitted
I actually suspect there might be a network/IO issue at play but wanted to
check with this group to see if anyone had an idea on this issue or how I
might get more information from the pool about why this is happening?
Thank You!!
Ryan Bergman
