Bug 63210 - Tomcat failing to shutdown if EvictionTimer thread is running
Summary: Tomcat failing to shutdown if EvictionTimer thread is running
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 9.0.x
Hardware: PC Mac OS X 10.1
: P2 normal (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-02-26 04:55 UTC by kirk
Modified: 2019-03-07 01:21 UTC (History)
0 users



Attachments
stacktrace showing servlet initialization in 8.0.53 (1.48 KB, text/plain)
2019-02-26 04:55 UTC, kirk
Details
stacktrace showing servlet initialization in 9.0.16 (3.69 KB, text/plain)
2019-02-26 04:56 UTC, kirk
Details
Thread dump after Tomcat fails to stop (5.75 KB, text/plain)
2019-02-26 04:56 UTC, kirk
Details
Example servlet source to replicate the issue (2.64 KB, text/plain)
2019-02-26 04:58 UTC, kirk
Details
Example war for the replication case (4.28 KB, application/zip)
2019-02-26 04:59 UTC, kirk
Details
context configuration file for replication case (318 bytes, text/xml)
2019-02-26 04:59 UTC, kirk
Details
Patch that fixes this specific case with the EvictionTimer thread (708 bytes, patch)
2019-02-26 04:59 UTC, kirk
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description kirk 2019-02-26 04:55:34 UTC
Created attachment 36463 [details]
stacktrace showing servlet initialization in 8.0.53

If a query is executed against a DataSource during the Servlet init phase when timeBetweenEvictionRunsMillis is defined on the DataSource when you try and shutdown Tomcat it will shutdown everything but the commons-pool-evictor-thread is left waiting and will not shut down (regardless of the value set in the timeBetweenEvictionRunsMillis).

I found this issue as part of upgrading a webapp from working with Tomcat 8.0.53 to 9.0.16. It is caused by a change of behaviour between the two versions due to initialization of the Servlets happening in a different way between the two versions, namely that the Servlet initialization in Tomcat 8.0.53 happens in a separate thread, whereas with 9.0.x it happens on the main thread.

This means that when the EvictionTimer thread is started it inherits the daemon flag from the parent thread (as it isn't explicitly set) which is false in 9.0.x and true in 8.0.53 and therefore when the main thread exits after shutdown in 9.0.x the common-pool-evictor-thread continues and stops termination of Tomcat.

There is a workaround for this - by manually closing the underlying datasource during the Servlet destroy method.

There are potentially two issues here:
1. The EvictionTimer thread should be marked as setDaemon after it is created (in the EvictorTimerFactory) this way it'll be killed when Tomcat is shutdown. See the attached diff which I've confirmed fixes the issue.

2. The resources are not actually being closed if they are loaded via a reference in the context.

#2 here is perhaps the bigger issue - this may be an issue for more than just the EvictionTimer, but it was the one I hit.


Full Replication steps:
1. Put the attached test.war into the base tomcat direct

This war file was a simple webapp based upon:

https://www.journaldev.com/2513/tomcat-datasource-jndi-example-java

You'll need to create the database with the tables as described in that example. For reference I was using PostgreSQL.

I've modified the source of the servlet however as attached (TestServlet.java) - namely it is now loading the JNDI DataSource during the Servlet.init() method and executing the same getEmployees query in the init method to ensure datasource pool initialized at that point.

2. create the context for the webapp - put the attached test.xml into conf/Catalina/localhost/test.xml.
Note this is using a Resource for the DataSource and setting the timeBetweenEvictionRunsMillis="60000".

You'll need to change the database configuration (url, driverClassname) in the Resource to point to your database.

3. Create the database and populate the tables (see the attached link)
4. Start up Tomcat using bin/start.sh
5. Connect to http://localhost:8080/test/ to confirm the servlet is loaded and working
6. Shutdown Tomcat using bin/shutdown.sh

It'll say it is shutdown - and to ensure that it isn't stuck in the eviction wait time wait at least 60 seconds - but if you look at your processes you'll see the Tomcat instance is still running with a similar list of threads as seen in the attached jstack.log.  



The Servlet is producing the stacktrace during the init that shows the difference between the 9.0.x startup and the 8.0.53 startup (full stack traces are attached).

8.0.53 startup looks like:
26-Feb-2019 10:26:18.071 INFO [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.log java.lang.Exception
	at test.TestServlet.init(TestServlet.java:28)
	at javax.servlet.GenericServlet.init(GenericServlet.java:158)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:118
       // snip

	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834) 


Whereas the 9.0.16 stacktrace traces back to the Bootstrap main method:

Feb. 26, 2019 8:42:08 AM org.apache.catalina.core.ApplicationContext log
INFO: java.lang.Exception
	at test.TestServlet.init(TestServlet.java:28)
	at javax.servlet.GenericServlet.init(GenericServlet.java:158)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1123)
	// snip
	at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:350)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:492)
Comment 1 kirk 2019-02-26 04:56:24 UTC
Created attachment 36464 [details]
stacktrace showing servlet initialization in 9.0.16
Comment 2 kirk 2019-02-26 04:56:59 UTC
Created attachment 36465 [details]
Thread dump after Tomcat fails to stop
Comment 3 kirk 2019-02-26 04:58:28 UTC
Created attachment 36466 [details]
Example servlet source to replicate the issue
Comment 4 kirk 2019-02-26 04:59:01 UTC
Created attachment 36467 [details]
Example war for the replication case
Comment 5 kirk 2019-02-26 04:59:27 UTC
Created attachment 36468 [details]
context configuration file for replication case
Comment 6 kirk 2019-02-26 04:59:57 UTC
Created attachment 36469 [details]
Patch that fixes this specific case with the EvictionTimer thread
Comment 7 Remy Maucherat 2019-03-01 14:15:45 UTC
I was not aware the inline executor optimization was a 9.0 only feature, so the big difference is actually there. To get the same deployment thread behavior on Tomcat 9, you can enable parallel deployment and configure the daemon flag on the utility threads.

The proposed patch is rather obvious, no problem.
Comment 8 Mark Thomas 2019-03-04 13:17:19 UTC
The proposed patch is not the correct solution. It addresses issue #1 in the original description but the real problem appears to be issue #2. If issue #2 is fixed then issue #1 will be fixed too.

I'm looking to see if I can reproduce this locally.
Comment 9 Mark Thomas 2019-03-04 15:16:33 UTC
I am able to recreate the locally. Still investigating the root cause as I'd expect the DataSource to be shutdown cleanly when the web application stops.
Comment 10 Mark Thomas 2019-03-04 17:09:31 UTC
DBCP2 (actually Pool2) requires explicit shutdown and is documented as such. If it is shutdown (via closeMethod="close") then the Evictor thread is stopped.

My current thinking is to set closeMethod="close" if we create a DataSource resource using the built-in factory and to do so in such as way that the user can override it if they wish. I need to test this works as expected.
Comment 11 Mark Thomas 2019-03-04 20:27:07 UTC
Fixed in:
- trunk for 9.0.17 onwards
- 8.5.x for 8.5.39 onwards
Comment 12 kirk 2019-03-05 05:08:09 UTC
(In reply to Mark Thomas from comment #10)
> DBCP2 (actually Pool2) requires explicit shutdown and is documented as such.
> If it is shutdown (via closeMethod="close") then the Evictor thread is
> stopped.
> 
> My current thinking is to set closeMethod="close" if we create a DataSource
> resource using the built-in factory and to do so in such as way that the
> user can override it if they wish. I need to test this works as expected.

I've just built and tested from the git repository source - the implementation works as you have implemented - it shuts down correctly without the value set, and fails to shutdown if closeMethod="" is used.

It actually doesn't fix my use case but that is because we implement our own factory that returns the BasicDataSource. However it does point me to the correct solution, which is to set the closeMethod="close" in my case (I thought I had tried this) - which already works with 9.0.16.

I guess the only change that could make this more generic is to test the actualResource for implementing AutoClosable e.g. something like:

Object actualResource = envCtx.lookup(resource.getName());
+ if (!resource.isCloseMethodConfigured() && actualResource instanceof AutoCloseable) {
+   resource.setCloseMethod("close");
+ }
Comment 13 Mark Thomas 2019-03-05 10:37:18 UTC
That is actually a much neater solution. I'll rework the fix. Thanks.
Comment 14 Mark Thomas 2019-03-05 11:03:08 UTC
Improved fix applied (fixed versions as before).
Comment 15 kirk 2019-03-07 01:21:16 UTC
(In reply to Mark Thomas from comment #14)
> Improved fix applied (fixed versions as before).

I've built and tested with both the replication case and our use case with a custom DataSource factory and they are both working.

Thanks!