12

When I shut down Tomcat, I observe a correct shutdown and cleanup of the Spring WebApplicationContext. However, when I redeploy my Spring-based WAR (by copying the new WAR to webapps), normal shutdown does not occur. This is a problem for me due to all the ensuing resource leaks:

org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [] appears to have started a thread named [hz.hazelcast-swipe-instance.scheduled] but has failed to stop it. This is very likely to create a memory leak.
org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [] appears to have started a thread named [hz.hazelcast-swipe-instance.operation.thread-0] but has failed to stop it. This is very likely to create a memory leak.

... and many more. I am using XML-less configuration, this is my WebApplicationInitializer:

public class WebApplicationInitializer extends AbstractAnnotationConfigDispatcherServletInitializer
{
  @Override protected Class<?>[] getRootConfigClasses() {
    return new Class[] { WebSecurityConfig.class, WebMvcConfig.class };
  }
  @Override protected Class<?>[] getServletConfigClasses() { return null; }

  @Override protected String[] getServletMappings() { return new String[] { "/" }; }

  @Override public void onStartup(ServletContext ctx) throws ServletException {
    ctx.setInitParameter("spring.profiles.active", "production");
    super.onStartup(ctx);
  }
}

There is no configuration specific to controlling the behavior upon servlet context reload, and I assume this should have worked out of the box.

Is there a way to make the WebApplicationContext close properly before continuing the servlet context reloading procedure?

I am on Spring 4.0.5, Tomcat 7.0.54, Hazelcast 3.2.1, Hibernate 4.3.4.Final.

Update

I have added a Spring application listener for the ContextClosedEvent and printed the stack trace of its invocation:

    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:333) [spring-context-4.0.6.RELEASE.jar:4.0.6.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:335) [spring-context-4.0.6.RELEASE.jar:4.0.6.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:880) [spring-context-4.0.6.RELEASE.jar:4.0.6.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:841) [spring-context-4.0.6.RELEASE.jar:4.0.6.RELEASE]
    at org.springframework.web.servlet.FrameworkServlet.destroy(FrameworkServlet.java:819) [spring-webmvc-4.0.6.RELEASE.jar:4.0.6.RELEASE]
    at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1486) [catalina.jar:7.0.54]
    at org.apache.catalina.core.StandardWrapper.stopInternal(StandardWrapper.java:1847) [catalina.jar:7.0.54]
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232) [catalina.jar:7.0.54]
    at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5647) [catalina.jar:7.0.54]
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232) [catalina.jar:7.0.54]
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1575) [catalina.jar:7.0.54]
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1564) [catalina.jar:7.0.54]

This indicates that the Spring shutdown occurs in its Servlet#destroy method. This is the relevant snippet from AbstractApplicationContext#close():

        if (logger.isInfoEnabled()) {
            logger.info("Closing " + this);
        }

        LiveBeansView.unregisterApplicationContext(this);

        try {
            // Publish shutdown event.
            publishEvent(new ContextClosedEvent(this));
        }
        catch (Throwable ex) {
            logger.warn("Exception thrown from ApplicationListener handling ContextClosedEvent", ex);
        }
        // Stop all Lifecycle beans, to avoid delays during individual destruction.
        try {
            getLifecycleProcessor().onClose();
        }
        catch (Throwable ex) {
            logger.warn("Exception thrown from LifecycleProcessor on context close", ex);
        }

        // Destroy all cached singletons in the context's BeanFactory.
        destroyBeans();

        // Close the state of this context itself.
        closeBeanFactory();

        // Let subclasses do some final clean-up if they wish...
        onClose();

        synchronized (this.activeMonitor) {
            this.active = false;
        }

I see the log entry from the start of this snippet, and I get my ContextClosedEvent. I also see an entry DefaultLifecycleProcessor - Stopping beans in phase 2147483647, which probably comes from the getLifecycleProcessor.onClose() line. It seems that some error occurs downstream from that. Some exception may be swallowed.

Update 2

As requested, this is how I configure Hazelcast:

@Bean(destroyMethod="shutdown") public HazelcastInstance hazelcast() {
  final Config c = hzConfig();
  final JoinConfig join = c.getNetworkConfig().getJoin();
  join.getMulticastConfig().setEnabled(false);
  join.getTcpIpConfig().setEnabled(true);
  return getOrCreateHazelcastInstance(c);
}

hzConfig() is a method where instance name, group name and password, map names, and map indices are configured, so I don't think it is of interest here.

And this is my Hibernate SessionFactory config:

@Bean
public LocalSessionFactoryBean sessionFactory() {
  final LocalSessionFactoryBean b = new LocalSessionFactoryBean();
  b.setDataSource(dataSource);
  b.setHibernateProperties(props(
      "hibernate.connection.release_mode", "on_close",
      "hibernate.id.new_generator_mappings", "true",
      "hibernate.hbm2ddl.auto", "update",
      "hibernate.order_inserts", "true",
      "hibernate.order_updates", "true",
      "hibernate.max_fetch_depth", "0",
      "hibernate.jdbc.fetch_size", "200",
      "hibernate.jdbc.batch_size", "50",
      "hibernate.jdbc.batch_versioned_data", "true",
      "hibernate.jdbc.use_streams_for_binary", "true",
      "hibernate.use_sql_comments", "true"
  ));
  return b;
}
Community
  • 1
  • 1
Marko Topolnik
  • 195,646
  • 29
  • 319
  • 436
  • It seems you have some scheduled tasks running in other thread which are out of spring context and they are not being able to be stopped when spring context is closing. – apurvc Jul 15 '14 at 16:59
  • It's hazalcast infrastructure, and it all gets properly shut down when the application context closes. – Marko Topolnik Jul 15 '14 at 20:43
  • Have you tried to use the admin manager app of the tomcat to redeploy your war instead of copying it? – Jorge Campos Jul 23 '14 at 16:14
  • @JorgeCampos I have deleted the admin manager because I perceive it as a security risk. – Marko Topolnik Jul 23 '14 at 16:19
  • Can you share more of your hazelcast configuration details? The threads that Tomcat is complaining about are related to Hazelcast. – Andrei Stefan Jul 29 '14 at 07:24
  • @AndreiStefan I can, but the config is very basic and everything works fine when a normal shutdown occurs. The threads Tomcat is complaining about are just the end symptom, and the root cause is failure to properly complete the context closing procedure, a part of which is calling `HazelcastInstance#shutdown`. My main issue is that logging goes mute during servlet context destruction (I guess this is related to class loading) so I don't see any error. – Marko Topolnik Jul 29 '14 at 07:29
  • I can understand that, but in a situation like this I'd like to try and reproduce it and investigate this locally with hands-on work. I'm not familiar with Hazelcast but I can see it's being used in various scenarios and I don't know how you are using it. If the configuration is very basic, then it's easier for me to come up with a sample app to try and reproduce it. That's the reason for my question. – Andrei Stefan Jul 29 '14 at 07:32
  • @AndreiStefan I have just edited the question. I am also configuring a Hibernate SessionFactory, you'll need that as well... – Marko Topolnik Jul 29 '14 at 07:33
  • What version of Hazelcast does your app use? – Andrei Stefan Jul 29 '14 at 08:39
  • @AndreiStefan I am on 3.2.1. I have updated the question with this as well. – Marko Topolnik Jul 29 '14 at 09:24
  • I've tested this but I'm not seeing anything related to hazelcast when hot redeploying. Haven't added Hibernate, yet, though. The Tomcat instance you have is the standard one? If you simply get the .zip from apache.org and test it as is, do you get the same output? – Andrei Stefan Jul 29 '14 at 09:27
  • @AndreiStefan Yes, I just got the .zip and added the Postgresql JDBC driver to the lib directory. No other customizations were performed. – Marko Topolnik Jul 29 '14 at 09:35
  • What's the relationship between Hibernate and Hazelcast? I've seen it can be configured as a second level cache, but I'm not seeing this in your Hibernate config. – Andrei Stefan Jul 29 '14 at 10:25
  • No relationship, but the error may be coming from anywhere and Hibernate is one other such thing which acquires substantial resources (DB connections). We are stumbling in the dark here, really, and I am quite demoralized as to my chances of solving this. – Marko Topolnik Jul 29 '14 at 10:29
  • You should shutdown hazelcast instance on application context destroyed, `yourHazelcastInstance.getLifecycleService().shutdown();` or shutdown all previous instances with `Hazelcast.shutdownAll();` – vzamanillo Jul 29 '14 at 10:29
  • @vzamanillo Why precisely should I do that instead of what I do now, which is provide Spring with the name of the destroy method? Note that the way it is currently already works properly for normal Tomcat shutdown. – Marko Topolnik Jul 29 '14 at 10:30
  • Any chances you could share your app or a smaller one (but one that could reproduce the behavior you see)? – Andrei Stefan Jul 29 '14 at 10:33
  • @AndreiStefan Not on a short timescale as I am fully occupied with the continued development of this app. Sorry. – Marko Topolnik Jul 29 '14 at 10:34
  • Ok. One other thing. Apart from those two threads from Hazelcast, what other resources you get in logs that could "cause memory leaks"? – Andrei Stefan Jul 29 '14 at 10:35
  • @AndreiStefan Just a bunch more Hazelcast-started threads, some 25 altogether. – Marko Topolnik Jul 29 '14 at 10:39
  • Ok, so only Hazelcast? In my sample app, after looking at it with JConsole I see a bunch of hazelcast threads. So, I'm assuming everything that Hazelcast starts it's causing you issues. This is a bit of narrowing down the issue. Do you do anything else with that `hazelcast()` `@Bean` other than defining it? Also, where do you have that definition (in `WebMvcConfig` or `WebSecurityConfig`)? – Andrei Stefan Jul 29 '14 at 10:42
  • @AndreiStefan As I said, clearly Hazelcast is not getting shut down, but the reason for that is most likely not due to Hazelcast, but to some error happening *upstream* in the shutdown procedure, which curtails it so the `shutdown` method is never called on the Hazelcast instance. – Marko Topolnik Jul 29 '14 at 10:51
  • @AndreiStefan Answering your specific questions, I don't do anything with the instance, just start it; I have it in the *root application context* and I don't have anything in the web application context. This was needed to circumvent earlier issues. – Marko Topolnik Jul 29 '14 at 10:52
  • Then enable remote debugging in your Tomcat instance and place a breakpoint at the line you have in logs (`DefaultLifecycleProcessor - Stopping beans in phase 2147483647`) and spend some time debugging. – Andrei Stefan Jul 29 '14 at 11:00
  • @AndreiStefan Yes, that is one of the options. Thanks for trying to help. Also note that I wouldn't have bothered to ask the question at all if I knew at the outset that the problem was a swallowed exception. The issue seemed much simpler at the time when I was writing the question. – Marko Topolnik Jul 29 '14 at 11:03
  • @MarkoTopolnik, do you have log files of a failed hot redeploy and a normal shutdown? Maybe there are some clues in there comparing a successful and an unsuccessful "shutdown". In one of my tests, I've put a bogus method as a `destroyMethod`. Of course, Spring complained, thrown some exceptions and I got to see the threads that were "very likely to create a memory leak". As I know Spring, I'm inclined to believe this doesn't come from it (there had to be some kind of message saying anything about things going wrong). But maybe a comparison of log files might reveal something. – Andrei Stefan Jul 29 '14 at 12:48
  • @AndreiStefan I had it it an earlier edition of the question, but then I have replaced it with the narrower diagnostic in my **Update**. There I describe what I see in the logs and to what line in the `close` method each of these log entries relates. – Marko Topolnik Jul 29 '14 at 13:09
  • @AndreiStefan What I think I should test is how an exception thrown from a destroy method is manifested in the logs. – Marko Topolnik Jul 29 '14 at 13:16
  • I'm curious: I've looked at the history of the post and you had a logback exception in there; did you manage to fix it? As you saw, that was thrown when trying to log something during a `catch()`. – Andrei Stefan Jul 29 '14 at 13:20
  • @AndreiStefan That was bogus, it was caused by my code in the context closed listener which I introduced just for debugging. It went away when I replaced it with `System.err.println`. But it did show that classloading is compromised at this point in the shutdown procedure. – Marko Topolnik Jul 29 '14 at 13:22
  • You can try enabling the Hazelcast logging to see what LifecycleService does, and maybe your problem is related to this issue https://github.com/hazelcast/hazelcast/issues/2454 – vzamanillo Jul 29 '14 at 14:09
  • @vzamanillo I have set Hazelcast logging to slf4j, I see an error in the logs related to Spring *trying* to log an error, but failing due to classloading issues with logback. I can see into that further. – Marko Topolnik Jul 29 '14 at 14:29
  • @AndreiStefan, vzamanillo: My most likely candidate explanation at the moment is that an attempt to log something with logback inside a `destroyMethod` of a bean fails with an exception, which is then swallowed because all further attempts to log that exception fail as well. I'll try that out tomorrow. – Marko Topolnik Jul 29 '14 at 15:28
  • @MarkoTopolnik news about the issue? – vzamanillo Jul 30 '14 at 07:17
  • @vzamanillo Yes, but no good ones. I have removed the logback dependency; that changed behavior to a 30-second pause after which the same memory leak warnings are issued. There is again a log statement in the `localhost.*` log (not seen in `catalina.out`) again indicating classloading problem, just with a different class (Spring's `ContextCleanupListener`). – Marko Topolnik Jul 30 '14 at 08:34
  • Are you doing any custom classloading stuff? I'm assuming this is a .war with jars packed in WEB-INF/lib. Any duplicate jars in there? (same lib but different jar) – Andrei Stefan Jul 30 '14 at 08:56
  • Different version, I meant. Sorry. – Andrei Stefan Jul 30 '14 at 09:05
  • @AndreiStefan No, nothing like that. Classloading issues occur only during context reloading and, for instance, the logback class which I had problems with is being used all the time, without trouble, until context reload. – Marko Topolnik Jul 30 '14 at 09:27
  • Can you try something: in your Tomcat, go to `/conf/context.xml` and place a `antiResourceLocking="true" antiJARLocking="true"` to the `` element? – Andrei Stefan Jul 30 '14 at 10:41
  • @AndreiStefan You've hit jackpot with this one... now reloading is working properly. Note that only one of those two options should be used; I have tried and just `antiJARLocking` is not enough, but `antiResourceLocking` works. – Marko Topolnik Jul 30 '14 at 11:19
  • Finally :-), glad it's working now. With your permission I'll add an answer. – Andrei Stefan Jul 30 '14 at 11:20

4 Answers4

7

At some point, you mentioned that there was a NoClassDefFoundError for Logback. You got this fixed by removing this dependency, but then the problem moved to a another class - one of Spring's own classes.

This can mean that either one of the libraries you have does something buggy with class loaders or maybe Tomcat needs instructions not to keep locks on some resources. See here more about Tomcat resources being locked and the <Context> setting to try: in your Tomcat's conf/context.xml place a antiResourceLocking="true" to the element.

Andrei Stefan
  • 51,654
  • 6
  • 98
  • 89
5

Have you tried upping unloadDelay (defaults to 2000ms) for Tomcat contexts? See http://tomcat.apache.org/tomcat-7.0-doc/config/context.html

UPDATE: I see that you are having issues with logback as well, it might be worth the shot to try and register this listener as well:

class LogbackShutdownListener implements ServletContextListener {

    @Override
    public void contextDestroyed(ServletContextEvent event) {
        LoggerContext loggerContext = (LoggerContext)LoggerFactory.getILoggerFactory();
        System.out.println("Shutting down Logback context '" + loggerContext.getName() + "' for " + contextRootFor(event));
        loggerContext.stop();
    }

    @Override
    public void contextInitialized(ServletContextEvent event) {
        System.out.println("Logback context shutdown listener registered for " + contextRootFor(event));
    }

    private String contextRootFor(ServletContextEvent event) {
        return event.getServletContext().getContextPath();
    }

}

Be sure to declare this listener before the spring context loader listener so that it is invoked after the context listener upon shutdown.

UPDATE 2: Also it might be worth the try to register another bean to handle closing of the Hazelcast stuff manually (be sure to also remove destroyMethod from the hazelcast bean):

@Component
class HazelcastDestructor {

    @Autowired
    private HazelcastInstance instance;

    @PreDestroy
    public void shutdown() {
        try {
            instance.shutdown();
        } catch (Exception e) {
            System.out.println("Hazelcast failed to shutdown(): " + e);
            throw e;
        }
    }  
}

UPDATE 3: Just out of curiosity, have you tried parallel deployment: http://www.javacodegeeks.com/2011/06/zero-downtime-deployment-and-rollback.html. It might behave differently than reloading the very same context. At the very least you should be able to undeploy the old version lazily and see if that makes a difference.

Jukka
  • 4,583
  • 18
  • 14
  • I can tell you right now that this is a great try. I'll get back to you tomorrow when I check it. – Marko Topolnik Jul 29 '14 at 20:53
  • Unfortunately this did not help, actually i get the Context Destroyed event within the first second of context reload. – Marko Topolnik Jul 30 '14 at 07:37
  • Bummer. See edited answer for something else to try. – Jukka Jul 30 '14 at 08:02
  • I know about these other avenues, but the problem is that the shutdown procedure is probably *aborted*, so 1) hazelcast not being shut down is not the only issue, just the "loudest" one, 2) these other avenues will probably fail just as well since the error is in the high-level control code (see the snippet in my question). – Marko Topolnik Jul 30 '14 at 08:36
  • One more thing to try (if you haven't tried it already), see update #3. – Jukka Jul 30 '14 at 09:30
  • I confirm that parallel deployment worked and I was able to cleanly undeploy a version. I can still not definitely conclude that this approach will work in all aspects in production, but it is a very good option in general and sidesteps the redeployment problems. – Marko Topolnik Jul 30 '14 at 10:30
  • Another option is to avoid reloading applications all together and provide HA (and zero-downtime updates) through load balancing and multiple Tomcat servers (with session replication if necessary). – Jukka Jul 30 '14 at 10:41
  • Yes, I am aware of that and it was actually planned at first, but due to time constraints the decision is to go live with a single server arrangement, later scaling out as necessary. – Marko Topolnik Jul 30 '14 at 10:47
1

There is a similar issue on the dangling threads while container restarting here.

Of all the answers, one particular answer of interest was by Howard - which shows the way these threads are cleared.

There is some good discussion and reasoning as to how this can terminate the threads here.

Now implement ServletContextListener and take care of these threads in the contextDestroyed() method as:

    public class YourListener implements ServletContextListener{
        ....
        @Override
        public void contextDestroyed(ServletContextEvent event) {
            //Call the immolate method here
        }
    }

Register this listener in WebApplicationInitilizer as:

     ctx.addListener(new YourListener());

So when server is restarted - contextDestroyed method is called and this takes care of all these threads.

Community
  • 1
  • 1
Prasad
  • 3,785
  • 2
  • 14
  • 23
1

From Web App development point of view, ServletContainer can only notify the before started and before end process of app. It is using ServletContextListener.

Config ServletContextListener in web.xml

<listener>
    <listener-class>com.var.YourListener</listener-class>
</listener>

YourListener.java

public class YourListener implements ServletContextListener {

    public void contextInitialized(ServletContextEvent sce) {
        //initialization process
    }
    public void contextDestroyed(ServletContextEvent sce) {
        //destory process
    }
}   

Update -XML Less

Programmatically

@Override 
public void onStartup(ServletContext ctx) throws ServletException {

    ctx.addListener(new YourContextListener());

    ctx.setInitParameter("spring.profiles.active", "production");
    super.onStartup(ctx);
}   

Annotation

@WebListener / @WebServletContextListener 
public class YourContextListener implements ServletContextListener {

    public void contextInitialized(ServletContextEvent servletContextEvent) {
    }

    public void contextDestroyed(ServletContextEvent servletContextEvent) {
    }
}

Update- ShoutDown Hook In Spring

I never use it before my app development, we can register shoutdownhook event into AbstractApplicationContext of Spring. I am not sure it will be ok or not for you.

AbstractApplicationContext context = ...
context.registerShutdownHook();

Reference 1 Reference 2

Community
  • 1
  • 1
Zaw Than oo
  • 9,651
  • 13
  • 83
  • 131
  • I have an XML-less Spring application. I don't have a web.xml. Also, when Tomcat is stopping, proper cleanup occurs. – Marko Topolnik Jul 24 '14 at 08:28
  • @MarkoTopolnik, you can use `org.springframework.web.context.ServletContextAware` like `ServletContextListener`. – Zaw Than oo Jul 24 '14 at 08:42
  • If you look at my updated question, you'll see that the problem is not in the signaling part (shutdown procedure start as expected); the problem is that there is a failure within the procedure, but without any trace in the logs. – Marko Topolnik Jul 24 '14 at 11:14