ServletContextListener.contextDestroyed() method not getting invoked on a "cf stop/delete" app

[Tony]

Hi Guys, 

I am trying to understand how apps, specifically how java webapps are shutdown by cloudfoundry. 

I have the following code in my java webapp.

public class TestContextListener implements ServletContextListener {

@Override

public void contextInitialized(final ServletContextEvent evt) {

System.out.println("#####################################################");

System.out.println("contextInitialized");

System.out.println("#####################################################");

}

@Override

public void contextDestroyed(final ServletContextEvent evt) {

System.out.println("#####################################################");

System.out.println("contextDestroyed");

System.out.println("#####################################################");

}

}

Logs:

2014-10-02T14:04:49.70-0500 [App/0]   OUT [CONTAINER] org.apache.coyote.http11.Http11NioProtocol         INFO    Initializing ProtocolHandler ["http-nio-61004"]

2014-10-02T14:04:49.71-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.startup.Catalina               INFO    Initialization processed in 417 ms

2014-10-02T14:04:49.72-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.core.StandardService           INFO    Starting service Catalina

2014-10-02T14:04:49.72-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.core.StandardEngine            INFO    Starting Servlet Engine: Apache Tomcat/8.0.12

2014-10-02T14:04:49.74-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.startup.HostConfig             INFO    Deploying web application directory /home/vcap/app/.java-buildpack/tomcat/webapps/ROOT

2014-10-02T14:04:53.29-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:53.29-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:53.29-0500 [App/0]   OUT contextInitialized

2014-10-02T14:04:53.30-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:53.30-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:55.75-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.startup.Catalina               INFO    Server startup in 6043 ms

2014-10-02T14:04:56.23-0500 [DEA]     ERR Instance (index 0) failed to start accepting connections

2014-10-02T14:06:05.58-0500 [API]     OUT Updated app with guid d235c71a-10e9-45b8-b878-55b4a5433c94 ({"state"=>"STOPPED"})

2014-10-02T14:06:05.58-0500 [App/0]   OUT Dropped a message because of read error: read unix /var/vcap/data/warden/depot/184edailtu7/jobs/40/stdout.sock: use of closed network connection

2014-10-02T14:06:05.58-0500 [App/0]   ERR 

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopping app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopped app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopping app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopped app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

So when my app is deployed I see the above context initialized logs. But when I do "cf stop/delete" i dont see logs from the contextDestroyed() method.

So after doing some investigation online came across this blog (http://blog.cloudfoundry.org/2012/06/18/deploying-tomcat-7-using-the-standalone-framework/ > Step 4 – Edit Tomcat Configuration) saying the cloudfoundry use "kill -9 $PID" to shutdown app/tomcat. 

But also came across this documentation (https://github.com/cloudfoundry/warden/tree/master/warden > Container Lifecycle > Destroy) which says that cloudfoundry  sends a "SIGTERM" first, waits for a couple of seconds and then sends a "SIGKILL" to shutdown the tomcat container where the app is deployed.

If this is true is there a way to configure this "wait for a couple of seconds before sending a 'SIGKILL'"  through some env or config file.

I need a way to execute some cleanup code in the contextDestroyed() method. 

If you guys can provide any pointers that would be very helpfull.

Thank  you.

[Daniel Mikusa]

On Thu, Oct 2, 2014 at 3:34 PM, Tony <star...@gmail.com> wrote:

Hi Guys, 

I am trying to understand how apps, specifically how java webapps are shutdown by cloudfoundry. 

I have the following code in my java webapp.

public class TestContextListener implements ServletContextListener {

@Override

public void contextInitialized(final ServletContextEvent evt) {

System.out.println("#####################################################");

System.out.println("contextInitialized");

System.out.println("#####################################################");

}

@Override

public void contextDestroyed(final ServletContextEvent evt) {

System.out.println("#####################################################");

System.out.println("contextDestroyed");

This might not be the best choice because there might be timing problem with writing to stdout as the app is being shutdown.  In other words, does this get written before loggregator stops listening to stdout because you stopped the app?

 

System.out.println("#####################################################");

}

}

Logs:

2014-10-02T14:04:49.70-0500 [App/0]   OUT [CONTAINER] org.apache.coyote.http11.Http11NioProtocol         INFO    Initializing ProtocolHandler ["http-nio-61004"]

2014-10-02T14:04:49.71-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.startup.Catalina               INFO    Initialization processed in 417 ms

2014-10-02T14:04:49.72-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.core.StandardService           INFO    Starting service Catalina

2014-10-02T14:04:49.72-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.core.StandardEngine            INFO    Starting Servlet Engine: Apache Tomcat/8.0.12

2014-10-02T14:04:49.74-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.startup.HostConfig             INFO    Deploying web application directory /home/vcap/app/.java-buildpack/tomcat/webapps/ROOT

2014-10-02T14:04:53.29-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:53.29-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:53.29-0500 [App/0]   OUT contextInitialized

2014-10-02T14:04:53.30-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:53.30-0500 [App/0]   OUT #####################################################

2014-10-02T14:04:55.75-0500 [App/0]   OUT [CONTAINER] org.apache.catalina.startup.Catalina               INFO    Server startup in 6043 ms

2014-10-02T14:04:56.23-0500 [DEA]     ERR Instance (index 0) failed to start accepting connections

2014-10-02T14:06:05.58-0500 [API]     OUT Updated app with guid d235c71a-10e9-45b8-b878-55b4a5433c94 ({"state"=>"STOPPED"})

2014-10-02T14:06:05.58-0500 [App/0]   OUT Dropped a message because of read error: read unix /var/vcap/data/warden/depot/184edailtu7/jobs/40/stdout.sock: use of closed network connection

2014-10-02T14:06:05.58-0500 [App/0]   ERR 

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopping app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopped app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopping app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

2014-10-02T14:06:16.81-0500 [DEA]     OUT Stopped app instance (index 0) with guid d235c71a-10e9-45b8-b878-55b4a5433c94

So when my app is deployed I see the above context initialized logs. But when I do "cf stop/delete" i dont see logs from the contextDestroyed() method.

See above. It may be happening, you just might not be seeing the log entry.

 

So after doing some investigation online came across this blog (http://blog.cloudfoundry.org/2012/06/18/deploying-tomcat-7-using-the-standalone-framework/ > Step 4 – Edit Tomcat Configuration) saying the cloudfoundry use "kill -9 $PID" to shutdown app/tomcat. 

This is very old.  Don't reference this.  It's for CFv1 and is not applicable anymore.

 

But also came across this documentation (https://github.com/cloudfoundry/warden/tree/master/warden > Container Lifecycle > Destroy) which says that cloudfoundry  sends a "SIGTERM" first, waits for a couple of seconds and then sends a "SIGKILL" to shutdown the tomcat container where the app is deployed.

As far as I know, this is accurate.  Last I heard it's SIGTERM, wait 10 seconds, SIGKILL.

 

If this is true is there a way to configure this "wait for a couple of seconds before sending a 'SIGKILL'"  through some env or config file.

I'm not sure.  If there is, it's probably from the service provider side and not the app developer side.  Maybe someone else can answer this one.

 

I need a way to execute some cleanup code in the contextDestroyed() method. 

It should work, in theory.  Maybe just try another way of verifying, other than writing to STDOUT.  If it still doesn't seem to be working, let us know. 

Dan

[Tony Stark]

I am not sure what else I can try to verify that the contextDestroyed() method got executed. I tried the default logging mechanism which we use which sends the logs to the logstash server and observed the same behavior. That is the logs form the "contextDestoryed()" method never made it to the logstash server. 

In the old model i would have attached a debugger to see if the execution control goes to that method. I am not sure if that is possible with apps running in cloudfoundry. 

I even tried adding a Thread.sleep(30000); after the logs to see if that gives enough time for the logs to get dumped before shutting down but no luck.

If you guys have any other suggestions to verify this or a way to increase this wait time between sending a "SIGTERM" and "SIGKILL" to a higher value that would be great.

Thank you.

--
You received this message because you are subscribed to the Google Groups "Cloud Foundry Developers" group.
To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/CAAqVxAxnty52f8K9tSXVkAcaVY_0dcQyX5DB7uz_D%3DM%2Bj9rtng%40mail.gmail.com.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[Tony]

I am not sure what else I can try to verify that the contextDestroyed() method got executed. I tried the default logging mechanism which we use which sends the logs to the logstash server and observed the same behavior. That is the logs form the "contextDestoryed()" method never made it to the logstash server. 

In the old model i would have attached a debugger to see if the execution control goes to that method. I am not sure if that is possible with apps running in cloudfoundry. 

I even tried adding a Thread.sleep(30000); after the logs to see if that gives enough time for the logs to get dumped before shutting down but no luck.

If you guys have any other suggestions to verify this or a way to increase this wait time between sending a "SIGTERM" and "SIGKILL" to a higher value that would be great.

Thank you.

[Dieu Cao]

There's not a way to configure the amount of time to wait between sending the "SIGTERM" and "SIGKILL"

We have a bug in our backlog around losing app logs during shutdown [1] that we'll likely be looking at in the next week or two.

[1] https://www.pivotaltracker.com/story/show/77564336

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+unsubscribe@cloudfoundry.org.

[Scott Frederick]

It is kind of hokey, but I verified this using a simple little app with a database, and just wrote a record to the DB from the shutdown hook to prove to myself that it was actually getting invoked. If you are just trying to see how the mechanism works, you might be able to do something similar until the story Dieu referenced fixes the logging problem. 

Scott

[Daniel Mikusa]

On Thu, Oct 2, 2014 at 5:10 PM, Scott Frederick <scott...@gmail.com> wrote:

It is kind of hokey, but I verified this using a simple little app with a database, and just wrote a record to the DB from the shutdown hook to prove to myself that it was actually getting invoked. If you are just trying to see how the mechanism works, you might be able to do something similar until the story Dieu referenced fixes the logging problem. 

Scott

+1 Exactly what I was thinking.

Dan

 

To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/7bf8a008-8db1-44e9-9c7b-d8f8d43cca5a%40cloudfoundry.org.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[James Bayer]

you can attach a debugger if the app has a network path to your debug client. see: http://mikusa.blogspot.com/2014/08/debugging-java-applications-on.html

To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/CAAqVxAyxZ22OovqT1OSR8gC-pJ%3DNHkCZqzPFZj7Q%3Dvdw%3D5qW6A%40mail.gmail.com.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

--

Thank you,

James Bayer

[Tony]

our apps use log4j2 socket appender and syslog appender to send the logs to our logstash server and we are not seeing any of the shutdown logs.

the issue tracker (https://www.pivotaltracker.com/story/show/77564336)  mentioned that the DEA is shutting down the socket so the logs are not sent to the log aggregator. I am assuming here that the DEA is shutting down all socket and syslog appender connections opened by an application. Can you guys confirm if this is the case.

If so then the fix for the above issue will resolve our issue as well. But if the DEA is only closing sockets to the log aggregator and the fix is to address only this behavior then we still might have an issue for people who might not be using the log aggregator.

Thanks.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[Tony]

Thanks Scott will try this.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[Tony]

This will be very usefull. I wasnt aware of this. Thanks.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

--
You received this message because you are subscribed to the Google Groups "Cloud Foundry Developers" group.

To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/7bf8a008-8db1-44e9-9c7b-d8f8d43cca5a%40cloudfoundry.org.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

--
You received this message because you are subscribed to the Google Groups "Cloud Foundry Developers" group.

To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/CAAqVxAyxZ22OovqT1OSR8gC-pJ%3DNHkCZqzPFZj7Q%3Dvdw%3D5qW6A%40mail.gmail.com.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[Tony]

Would it be possible to add a feature request to make this amount of time to wait between sending the "SIGTERM" and "SIGKILL" configurable. I can see this being very useful. Especially incases where an app might need more than 10 seconds to clean up resources being consumed.  

On Thursday, October 2, 2014 4:01:25 PM UTC-5, Dieu Cao wrote:

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[Dieu Cao]

We think it's fine to make a PR to make the amount of time to wait between sending the "SIGTERM" and "SIGKILL" configurable at the deployment level so that an operator can control this value.  We do think that clean shut downs are an optimization though and should not be necessary for reliability.  Also, we think there should still be some upper limit on this configuration so as not to stall rolling deploys.

-Dieu Cao

Cloud Foundry Runtime PM

[Onsi Fakhouri]

If we're agreed, then this needs to go in 3 backlogs: runtime, diego, and garden

To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/8f885283-0049-4c2a-9221-c2d449fe6ff3%40cloudfoundry.org.

[James Bayer]

at this point this was a feature request that i don't think the CF team plans to work on ourselves anytime soon. if someone wants to do a PR for this, then we should discuss it. i think no action is required for now unless someone intending to do a PR indicates they want to work on this.

To view this discussion on the web visit https://groups.google.com/a/cloudfoundry.org/d/msgid/vcap-dev/CAFwdB-zv5oEpB3YbEJGX5B6VenbuYJw1XVmX%2BgTFHR_QHRzPjg%40mail.gmail.com.

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

--

Thank you,

James Bayer