1

Suppose it is 2016. I am building a very simple Java EE app with Spring for DI, jdbc template and web, Oracle for persistence and Deploy it to Tomcat. Sounds easy, not sure if it could be more trivial.

There are the following most recent stable versions:

  • Tomcat 8.5
  • Oracle jdbc drivers v 12.x
  • and Spring 4.3.x

Tomcat recommends putting jdbc drivers to $CATALINA_BASE/lib, so I follow this recommendation. Oracle recommends using their UCP pool and tutorials at oracle.com also suggest putting ucp.jar together with ojdbc.jar (to Tomcat's lib folder). I use Spring to manage lifecycle of UCP pool and pass it as a datasource to JdbcTemplate.

I use a single dedicated server at production and for the best experience of my users I use a Tomcat's Parallel deployment feature. There is nothing very special about this feature, it allows to deploy a new version with no downtime and automatically (and gracefully) undeploy an old version when there are no active sessions left for it.

The missing ResultSetMetaData problem

The unexpected problem I may have after deploying a new version of application with such a simple setup:

INFO [http-nio-8080-exec-6] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [java.sql.ResultSetMetaData]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [java.sql.ResultSetMetaData]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
  at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1427)
  at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1415)
  at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1254)
  at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1215)
  at com.sun.proxy.$Proxy31.getMetaData(Unknown Source)
  at org.springframework.jdbc.core.SingleColumnRowMapper.mapRow(SingleColumnRowMapper.java:89)
  at org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:93)
  at org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:60)
  at org.springframework.jdbc.core.JdbcTemplate$1QueryStatementCallback.doInStatement(JdbcTemplate.java:465)
  at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:407)
  at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:477)
  at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:487)
  at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:497)
  at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:503)
  at example.App.rsMetadataTest(App.java:82)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:204)
  at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
  at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
  at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:854)
  at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:765)
  at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
  at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
  at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
  at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
  at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
  at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
  at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
  at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
  at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
  at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
  at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
  at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
  at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
  at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
  at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1726)
  at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
  at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
  at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
  at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
  at java.lang.Thread.run(Thread.java:748)

And now the app is broken. Any subsequent attempt to make a call involving ResultSetMetaData (i.e. jdbcTemplate.queryForObject("select 'hello' from dual", String.class)) will fail with:

java.lang.NoClassDefFoundError: java/sql/ResultSetMetaData
  com.sun.proxy.$Proxy31.getMetaData(Unknown Source)
  org.springframework.jdbc.core.SingleColumnRowMapper.mapRow(SingleColumnRowMapper.java:89)
  org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:93)
  org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:60)
  org.springframework.jdbc.core.JdbcTemplate$1QueryStatementCallback.doInStatement(JdbcTemplate.java:465)
  org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:407)
  org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:477)
  org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:487)
  org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:497)
  org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:503)
  example.App.rsMetadataTest(App.java:82)
  sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  java.lang.reflect.Method.invoke(Method.java:498)
  org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:204)
  org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
  org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
  org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:854)
  org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:765)
  org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
  org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
  org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
  org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
  org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
  javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
  org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
  javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
  org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)

How to reproduce

Unfortunately I do not understand the root cause of the exception. The ResultSetMetaData is a JDK class, how it can be not found? Was it unloaded? At least after some experiments I know exactly the minimum steps required to reproduce it:

  • deploy 1st version of an app and init db pool (i.e. with a simple connection, but which DOES NOT involve ResulstSetMetaData, i.e. jdbcTempalte.query()).
  • deploy the 2nd version of an app
  • wait for the 1st version to undeploy (as gracefully as possible)
  • and make a call which involves ResultSetMetaData.
  • Boom! The ResultSetMetaData not found again and the app is broken.

This bug does not depend on Tomcat's Parallel deployment feature. You can have the most recent (9.x) Tomcat with stock configuration, 2 different webapps using the same Oracle jdbc driver, deploy it in the order and under the same conditions I described above and get the same error.

Also I would like to add that the following statement from Tomcat is incorrect:

this web application instance has been stopped already

I know exactly that the 2nd (just deployed) app gets invoked (not the unloaded one), it is alive and could not be stopped. But it fails at reaching ResultSetMetaData on it's way.

With the help of docker-compose I did many experiments to isolate the problem and see what can fix it. One thing that fixes the problem is putting ucp.jar to .war, not into Tomcat's lib. That's the reason for the question in the title:

Should Oracle's ucp.jar reside in Tomcat's lib or be bundled to application's war?

ucp.jar itself is not a jdbc driver which gets registered with a global service-provider. Do you put HikariCP to Tomcat's lib? I do not think so. And bundling ucp to webapp fixes the ResultSetMetaData problem. Are there any other reasons for ucp.jar to be placed to Tomcat's lib?

Broken reflection

Unfortunately moving ucp.jar to war by setting compile or runtime scope for it in Maven can lead to another problem:

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'oracleDataSource' defined in example.App: Initialization of bean failed; nested exception is java.lang.ArrayStoreException: sun.reflect.annotation.AnnotationTypeMismatchExceptionProxy
  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:562)
  ....
  ... 64 more
Caused by: java.lang.ArrayStoreException: sun.reflect.annotation.AnnotationTypeMismatchExceptionProxy
  at sun.reflect.annotation.AnnotationParser.parseEnumArray(AnnotationParser.java:744)
  ...
  at java.lang.Class.getAnnotations(Class.java:3446)
  at org.springframework.transaction.annotation.AnnotationTransactionAttributeSource.determineTransactionAttribute(AnnotationTransactionAttributeSource.java:152)

The context won't start as soon as you add @EnableTransactionManagement in your Spring Java config or <tx:annotation-driven/> if you prefer XML. But I do want to use @Transactional annotations in my app. So I am stuck again. Here at least I was able to understand the problem. Spring 4 tries to read annotations on PoolDataSourceImpl to see if the bean needs to proxied to support annotation-based transaction control. The Class#getAnnotations() fails to read annotations on the PoolDataSourceImpl class, because oracle.jdbc.logging.annotations.Feature exists in both jars (ucp and jdbc). And there are 2 class loaders having different instances of Class<oracle.jdbc.logging.annotations.Feature>. The part of introspection capabilities on PoolDataSourceImpl is broken with a weird ArrayStoreExceotion! The presence of such an error is an argument for keeping both Oracle jars in the same classpath.

If you faced the above problems in 2016 (when there was no higher versions of Oracle driver), what would you do? I am asking this, because the project I work on is a bit stuck in the past. Earlier, upgrading Oracle driver had led to unexpected and unobvious problems in production, so at the nearest release we are hesitant to update the jdbc driver. But since the project was recently upgraded from Tomcat 7 to Tomcat 8, there is now a risk to face the missing ResultSetMetaData problem, which should be solved.

I forgot to say: you might face the stacktrace complaining on missing ResultSetMetaData in a previous version of Tomcat: 7.x. But it did not spoil the observable behaviour. Unlike Tomcat 9.x and 8.x, Tomcat 7.x printed the exception once, but somehow managed to execute the query and successfully handle the request. Tomcat 7.x did not break the app. Does it mean that modern Tomcat has the regression which Tomcat 7.x did not have?

The potential memory leak Tomcat warnings

What I also do not like at redeployment is the following lines at logs:

WARNING [Catalina-utility-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [app##1] appears to have started a thread named [Timer-0] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.Object.wait(Object.java:502)
 java.util.TimerThread.mainLoop(Timer.java:526)
 java.util.TimerThread.run(Timer.java:505)

WARNING [Catalina-utility-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [app##1] appears to have started a thread named [oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 oracle.jdbc.driver.BlockSource$ThreadedCachingBlockSource$BlockReleaser.run(BlockSource.java:329)

WARNING [Catalina-utility-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [app##1] appears to have started a thread named [InterruptTimer] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.Object.wait(Object.java:502)
 java.util.TimerThread.mainLoop(Timer.java:526)
 java.util.TimerThread.run(Timer.java:505)

Is it possible to fix them at all? From my tests they are not caused by UCP, but rather come from ojdbc.jar. I did not find any solution here. Neither latest version of ojdbc8 (or ojdbc11), nor using other pools or lifecycle methods of Oracle's UniversalConnectionPoolManager (as suggested here) have helped here. If you replace ojdbc with postgres database and driver, you won't see similar warnings and your logs will be clean.

The source code

I did not provide any code in the post, it is already pretty long, but I created a repo with the minimal application example and parameterised docker-compose test. So you can easily play with it and reproduce all the problems I mentioned with a single command: docker-compose rm -fs && docker-compose up --build

Kirill
  • 6,762
  • 4
  • 51
  • 81

2 Answers2

1

I am aware that you mentioned I use Spring to manage lifecycle of UCP pool and pass it as a datasource to JdbcTemplate but my advice will be to create your datasource as a tomcat resource (i.e., at the context level):

<Resource
   name="tomcat/UCPPool"
   auth="Container"
<!-- Defines UCP or JDBC factory for connections -->
   factory="oracle.ucp.jdbc.PoolDataSourceImpl"
<!-- Defines type of the datasource instance -->
   type="oracle.ucp.jdbc.PoolDataSource"
   description="UCP Pool in Tomcat"
<!-- Defines the Connection Factory to get the physical connections -->
   connectionFactoryClassName="oracle.jdbc.pool.OracleDataSource”
   minPoolSize="2"
   maxPoolSize="60"
   initialPoolSize="15"
   autoCommit="false"
   user="scott"
   password="tiger"
<!-- FCF is auto-enabled in 12.2.  Use this property only if you are using Pre 12.2 UCP
   fastConnectionFailoverEnabled=”true”  -->
<!-- Database URL -->
url="jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=tcp)(HOST=proddbclust
er-scan)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=proddb)))"
</Resource>

The example is obtained from the guide provided for Oracle when describing Configure Tomcat for UCP.

And try to acquire a reference to that datasource through JNDI:

@Bean
public DataSource dataSource() {
  final JndiDataSourceLookup dsLookup = new JndiDataSourceLookup();
  dsLookup.setResourceRef(false);
  DataSource dataSource = dsLookup.getDataSource("tomcat/UCPPool");
  return dataSource;
}

You are very likely facing a class loading issue and putting ucp.jar together with ojdbc.jar in your $CATALINA_BASE/lib and configuring this JNDI lookup can solve the problem.

Regarding your warnings, please, consider read this related SO question, especially this answer: it seems that there is a bug in the Oracle JDBC drive and an update to driver version 12.2 should solve the problem.

P.S.: Great question, very well documented!!

jccampanero
  • 50,989
  • 3
  • 20
  • 49
  • Thanks for the suggestion! I did not try that before. But unfortunately it does not solve any problem. With v12 drivers you will still get `ResultSetMetaData` problem, with any other drivers you will see warnings from Tomcat about potential memory leak. – Kirill Aug 23 '21 at 11:27
  • Thank you very much for the feedback @Kirill, I am sorry to hear that it doesn't solve the problem. I will dig into it. Please, regarding the warnings, see the updated answer, it looks like a bug in the JDBC Driver solved in version 12.2. Please, can you try? – jccampanero Aug 23 '21 at 13:20
  • I am _already_ using 12.2.0.1 (which has the `ResultSetMetaData` problem). All the drivers of higher version do not have this problem, but at the moment there are not enough resources for testing to make sure that jdbc driver upgrade won't lead to other unexpected problems(which already happened multiple times in the history of the app). Regarding the warnings about potential memory leaks: I am not able to get rid of them with ANY version of jdbc driver available at Maven central (from 12.x to 21.x). You can easily try it yourself, the docker-compose file is greatly parameterised. – Kirill Aug 23 '21 at 14:20
  • I see @Kirill. I would try to test the provided repo. Please, in the meantime, can you expand the noclassdeffoundexception error stack trace? – jccampanero Aug 23 '21 at 14:45
  • Added `ResultSetMetaData`-related stacktraces – Kirill Aug 23 '21 at 14:59
  • Thank you very much @Kirill. I found a possible similar [problem](https://www.ibm.com/mysupport/s/question/0D50z000062kLAl/how-to-resolve-the-compoundclassloader-leak-issue-when-using-oracle-12c-driver-with-websphere-application-server?language=es): as suggested, please, can you try including `OracleDriver.deregisterHack()` when your application is being terminated, when the Spring context is destroyed? – jccampanero Aug 23 '21 at 15:19
  • @Kirill I do not know if that last solution will work, I haven't found the mentioned `deregisterHack` in the docs. I will try your setup and see. Any way, in my opinion, the stack trace confirms the thread related error. Do you agree? – jccampanero Aug 23 '21 at 21:37
1

The messages "appears to have started a thread named [...] but has failed to stop it" point directly at the heart of the problem, which is a very common issue when re-deploying webapps within a webapp container, whether tomcat or jetty or any other. The issue is that some long-running threads were started by the app, but not explicitly shutdown, so they keep running, and hence they keep an instance of the WebappClassLoader for this webapp in memory, which references the classes previously loaded by it. When you then redeploy the same webapp, a new distinct WebappClassLoader with the same resources is created, which however doesn't have access to the classes loaded by the prior incarnation that the JVM is still referencing, thus leading to the NoClassDefFoundError.

There are only three general means of dealing with this: a) Always restart the webapp container when redeploying webapps. b) Fix all code in the webapps so that all such long-running threads are shut down. This means implementing ServletContextListeners that will perform explicit shutdown operations, stopping pool management threads etc. when the ServletContext is stopped (i.e. the webapp is undeployed). c) Relocate the offending code so it is not loaded by the WebappClassLoader but by the SystemClassLoader, and thus never goes out of scope. In this case you would achieve that by moving the ojdbc.jar to the system classpath (tomcat/lib) and the datasource definition to the server configuration file (tomcat/conf/server.xml). It is anyway a bad practice to include database drivers within a webapp, such fundamental code should be centrally located so that only one instance of it runs within the JVM. Having these inside webapps can lead to conflicts.

volkerk
  • 134
  • 1
  • 7