pmoneoingen / myschedule

Automatically exported from code.google.com/p/myschedule
0 stars 0 forks source link

Application fails to stop in Tomcat7 #70

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago
What steps will reproduce the problem?
1. Install the WAR and some Jobs into Tomcat7, using InMemoryJobStore
2. Stop Tomcat

No matter if 
myschedule.schedulerService.waitForJobsToComplete = true|false

*** LOG ***

INFO: Stopping service Catalina
26.01.2012 10:26:43 org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SCHWERWIEGEND: The web application [/myschedule] appears to have started a 
thread named [Scheduler_Worker-1] but has failed to stop it. This is very 
likely to create a memory leak
.
26.01.2012 10:26:43 org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SCHWERWIEGEND: The web application [/myschedule] appears to have started a 
thread named [Scheduler_Worker-2] but has failed to stop it. This is very 
likely to create a memory leak
.
26.01.2012 10:26:43 org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SCHWERWIEGEND: The web application [/myschedule] appears to have started a 
thread named [Scheduler_Worker-3] but has failed to stop it. This is very 
likely to create a memory leak
.
26.01.2012 10:26:43 org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SCHWERWIEGEND: The web application [/myschedule] appears to have started a 
thread named [Scheduler_Worker-4] but has failed to stop it. This is very 
likely to create a memory leak
.
26.01.2012 10:26:43 org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SCHWERWIEGEND: The web application [/myschedule] appears to have started a 
thread named [Scheduler_Worker-5] but has failed to stop it. This is very 
likely to create a memory leak
.
26.01.2012 10:26:43 org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SCHWERWIEGEND: The web application [/myschedule] appears to have started a 
thread named [Scheduler_QuartzSchedulerThread] but has failed to stop it. This 
is very likely to create 
a memory leak.

*** kill -3 shows ***

Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.4-b02 mixed mode):

"DestroyJavaVM" prio=10 tid=0x00007f8e4c76a000 nid=0x37c8 waiting on condition 
[0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Timer-0" daemon prio=10 tid=0x00007f8e44588800 nid=0x37de in Object.wait() 
[0x00007f8e51503000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000eff26f10> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x00000000eff26f10> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Scheduler_Worker-5" prio=10 tid=0x00007f8e4412b000 nid=0x37dc in Object.wait() 
[0x00007f8e51b5c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000c25be380> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:552)
        - locked <0x00000000c25be380> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"Scheduler_Worker-4" prio=10 tid=0x00007f8e44129000 nid=0x37db in Object.wait() 
[0x00007f8e51c5d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000c25be1a8> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:552)
        - locked <0x00000000c25be1a8> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"Scheduler_Worker-3" prio=10 tid=0x00007f8e44123800 nid=0x37da in Object.wait() 
[0x00007f8e51d5e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000c25bdfd0> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:552)
        - locked <0x00000000c25bdfd0> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"Scheduler_Worker-2" prio=10 tid=0x00007f8e44118000 nid=0x37d9 in Object.wait() 
[0x00007f8e51e5f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000c25bddf8> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:552)
        - locked <0x00000000c25bddf8> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"Scheduler_Worker-1" prio=10 tid=0x00007f8e44116800 nid=0x37d8 in Object.wait() 
[0x00007f8e51f60000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000c25bdc20> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:552)
        - locked <0x00000000c25bdc20> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"GC Daemon" daemon prio=10 tid=0x0000000040958800 nid=0x37d5 in Object.wait() 
[0x00007f8e5260e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000c2000140> (a sun.misc.GC$LatencyLock)
        at sun.misc.GC$Daemon.run(GC.java:100)
        - locked <0x00000000c2000140> (a sun.misc.GC$LatencyLock)

Original issue reported on code.google.com by thomas.h...@gmail.com on 26 Jan 2012 at 9:36

GoogleCodeExporter commented 9 years ago
Hello Thomas,

Thanks for reporting issue. Can you show me what's the config properties you 
used for your scheduler?

Original comment by saltnlight5 on 26 Jan 2012 at 1:11

GoogleCodeExporter commented 9 years ago
It seems a known problem that Tomcat(7) is not very graceful and does not wait 
long enough, but here somehow it blocks.

The properties file for the scheduler:

# Main Quartz configuration
org.quartz.jobStore.class = org.quartz.simpl.RAMJobStore
org.quartz.scheduler.skipUpdateCheck = true
org.quartz.scheduler.instanceName = Scheduler
org.quartz.scheduler.jobFactory.class = org.quartz.simpl.SimpleJobFactory

# Jobs from XML
org.quartz.plugin.jobInitializer.class = 
org.quartz.plugins.xml.XMLSchedulingDataProcessorPlugin
org.quartz.plugin.jobInitializer.fileNames = jobs.xml
org.quartz.plugin.jobInitializer.failOnFileNotFound = true
org.quartz.plugin.jobInitializer.scanInterval = 30
org.quartz.plugin.jobInitializer.wrapInUserTransaction = false

# Logging
org.quartz.plugin.jobHistory.class = 
org.quartz.plugins.history.LoggingJobHistoryPlugin

# Pool
org.quartz.threadPool.class = org.quartz.simpl.SimpleThreadPool
org.quartz.threadPool.class=org.quartz.simpl.SimpleThreadPool
org.quartz.threadPool.threadCount=5
org.quartz.threadPool.threadPriority=4

# MySchedule scheduler service parameters (These are not used by quartz itself, 
but for the webapp only.)
myschedule.schedulerService.autoInit = true
myschedule.schedulerService.autoStart = true
myschedule.schedulerService.waitForJobsToComplete = true

Original comment by thomas.h...@gmail.com on 26 Jan 2012 at 2:46

GoogleCodeExporter commented 9 years ago
Thomas,

I use Tomcat myself, and I have tested MySchedule that it should shutdown 
gracefully.

In your case, I noticed that you set 
myschedule.schedulerService.waitForJobsToComplete = true, and you have loaded 
jobs.xml upson startup. Can you try to not load jobs.xml and see if your Tomcat 
will shutdown cleanly? If yes, then that means Quartz is blocking while trying 
to wait for your job to complete.

Another note is that if your jobs are taking a while to stop, which is okay, 
and Tomcat should wait for your webapp context to destroy gracefully. The only 
time this is not happening is if I run this under Cygwin terminal, and I use 
CTRL+C on the foreground process. Somehow Cygwin terminal will ends JVM 
abruptly without wait on CTRL+C. Is this what you are doing?

Original comment by saltnlight5 on 27 Jan 2012 at 1:36

GoogleCodeExporter commented 9 years ago
I see the similar issue running the application in TOMCAT 7.0.20 on Windows 7 
(64 bits os).

Here is what in the tomcat log file after issuing shutdown command. 

INFO: Pausing ProtocolHandler ["ajp-bio-8009"]
Jan 28, 2012 11:36:32 AM org.apache.catalina.core.StandardService stopInternal
INFO: Stopping service Catalina
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesJdbc
SEVERE: The web application [/myschedule] registered the JDBC driver 
[org.postgresql.Driver] but failed to unregister it when the web application 
was stopped. To prevent a memory leak, the JDBC Driver has been forcibly 
unregistered.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Sched_ex_13_Worker-1] but has failed to stop it. This is very likely to 
create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Sched_ex_13_Worker-2] but has failed to stop it. This is very likely to 
create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Sched_ex_13_Worker-3] but has failed to stop it. This is very likely to 
create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Sched_ex_13_Worker-4] but has failed to stop it. This is very likely to 
create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Sched_ex_13_Worker-5] but has failed to stop it. This is very likely to 
create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Timer-0] but has failed to stop it. This is very likely to create a 
memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] but has 
failed to stop it. This is very likely to create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] but has 
failed to stop it. This is very likely to create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2] but has 
failed to stop it. This is very likely to create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.catalina.loader.WebappClassLoader 
clearReferencesThreads
SEVERE: The web application [/myschedule] appears to have started a thread 
named [Sched_ex_13_QuartzSchedulerThread] but has failed to stop it. This is 
very likely to create a memory leak.
Jan 28, 2012 11:36:35 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["http-bio-8080"]
Jan 28, 2012 11:36:35 AM org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["ajp-bio-8009"]
Jan 28, 2012 11:36:35 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["http-bio-8080"]
Jan 28, 2012 11:36:35 AM org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["ajp-bio-8009"]

In my case, I am using JDBCStore and the DB conection pool is not being relaesd 
either.

I tested with different start up configurations with 
myschedule.schedulerService.waitForJobsToComplete set to "false". 

If I do not set autoInit property, TOMCAT shutdown cleanly. 

However, if I set the autoInit property to true and set autoStart=false, the 
issue shows up and I had to Ctrl-C to kill the app.

Original comment by jinh...@gmail.com on 28 Jan 2012 at 3:49

GoogleCodeExporter commented 9 years ago
I went through some debug session on this issue and find the problem may be 
related to the ServiceContainer::stopService() and 
ServiceContainer::destroyService(). The counter seems to be off by one.

Here is the code that works when shuting down the Tomcat (notice the >=0, 
instead of > 0 ).

    @Override
    protected void stopService() {
        // Stopping in reverse order.
        for (int i = services.size() - 1; i >= 0; i--) {
            Initable service = services.get(i);
            if (service instanceof Service) {
                logger.debug("Stopping service {}.", service);
                ((Service)service).stop();
                logger.info("Service {} stopped.", service);
            }
        }   
    }

    @Override
    protected void destroyService() {
        // Destroying in reverse order.
        for (int i = services.size() - 1; i >= 0; i--) {
            Initable service = services.get(i);
            logger.debug("Destroying service {}.", service);
            service.destroy();
            logger.info("Service {} destroyed.", service);
        }
    }

Original comment by jinh...@gmail.com on 28 Jan 2012 at 5:19

GoogleCodeExporter commented 9 years ago
Oops, that's must certainly a BUG! Thank you for the patch jinhfan!

I will fix this and push a new release out soon.

Original comment by saltnlight5 on 28 Jan 2012 at 4:16

GoogleCodeExporter commented 9 years ago
I think I know why my own testing didn't catch this. During testing, I always 
creates a InMememory scheduler first, then a Database one, so the index zero 
service for InMemeory one didn't give me trouble by not shutdown properly!

Original comment by saltnlight5 on 28 Jan 2012 at 4:25

GoogleCodeExporter commented 9 years ago
This issue was closed by revision 7a8715806c48.

Original comment by saltnlight5 on 28 Jan 2012 at 5:09

GoogleCodeExporter commented 9 years ago

Original comment by saltnlight5 on 28 Jan 2012 at 5:18