Re: [Wrapper-user] Shutdown hook does not have enough time to complete

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Please have a look at my first post, and look to the time of the log
statements.
Our setting for the timeouts in the wrapper.conf are:
wrapper.shutdown.timeout=200
wrapper.jvm_exit.timeout=200

This means, that the wrapper should wait 200 seconds for the jvm to exit.
Also your documentation says, that if the jvm_exit timeout is reached, a
message like

wrapper  | Shutdown failed: Timed out waiting for the JVM to terminate.
wrapper  | Java Virtual Machine did not exit on request, terminated

will be written to the log. There is no such message.

Also I compared your log and my one. They are not only different at the
beginning (You are maybe using the latest version 3.3.0-c, i am using
3.3.0-a), they are also different at the end. My log contains the
statements:

wrapperp | 2007/12/19 10:49:49 | socket read no code (closed?).
wrapperp | 2007/12/19 10:49:49 | server listening on port 32001.
jvm 1    | 2007/12/19 10:49:50 | WrapperManager Debug: calling System.exit
(0)
jvm 1    | 2007/12/19 10:49:50 | (Log INFO): Shutdown hook called

while your log has:
DEBUG  | wrapperp | 2007/12/21 11:00:44 | socket read no code (closed?).
DEBUG  | wrapperp | 2007/12/21 11:00:44 | server listening on port 32001.
INFO   | jvm 1    | 2007/12/21 11:00:44 | WrapperManager Debug: ShutdownHook
complete
INFO   | jvm 1    | 2007/12/21 11:00:44 | WrapperManager Debug: Server
daemon shut down
INFO   | jvm 1    | 2007/12/21 11:01:07 | Shutdown hook complete. Should
exit now.

As you can see, there is a "calling System.exit(0)" in my log.  This comes
from WrapperManager.shutdownJVM, line 3136.
Maybe it has something to do with the kind of starting the shutdown. Maybe
your should try your testcase using windows Service Mgmt Console to
shutdown.

What do you think about that?

markus

2007/12/21, Leif Mortenson <le...@ta...>:
>
> Markus,
> I went back today and retested how shutdown hooks work with the
> Wrapper today.
>
> This is the end of the debug log output for a shutdown hook which
> takes longer to run than the configured jvm_exit timeout.  Note
> that the WrapperManager's internal shutdown hook completes
> promptly, but the JVM does not actually terminate because the
> custom shutdown hook is still running:
> ---
> DEBUG  | wrapperp | 2007/12/21 10:43:46 | read a packet STOP : 0
> DEBUG  | wrapper  | 2007/12/21 10:43:46 | JVM requested a shutdown. (0)
> DEBUG  | wrapper  | 2007/12/21 10:43:46 | wrapperStopProcess(0) called.
> DEBUG  | wrapper  | 2007/12/21 10:43:46 | Sending stop signal to JVM
> DEBUG  | wrapperp | 2007/12/21 10:43:46 | send a packet STOP : NULL
> INFO   | jvm 1    | 2007/12/21 10:43:46 | WrapperManager Debug: Received
> a packet STOP :
> INFO   | jvm 1    | 2007/12/21 10:43:47 | WrapperManager Debug: Thread,
> Wrapper-Shutdown-Hook, handling the shutdown process.
> INFO   | jvm 1    | 2007/12/21 10:43:47 | WrapperManager Debug: calling
> listener.stop()
> INFO   | jvm 1    | 2007/12/21 10:43:47 | WrapperSimpleApp Debug: stop(0)
> INFO   | jvm 1    | 2007/12/21 10:43:47 | WrapperManager Debug: returned
> from listener.stop() -> 0
> INFO   | jvm 1    | 2007/12/21 10:43:47 | WrapperManager Debug:
> shutdownJVM(0) Thread:Wrapper-Shutdown-Hook
> INFO   | jvm 1    | 2007/12/21 10:43:47 | WrapperManager Debug: Send a
> packet STOPPED : 0
> DEBUG  | wrapperp | 2007/12/21 10:43:47 | read a packet STOPPED : 0
> DEBUG  | wrapper  | 2007/12/21 10:43:47 | JVM signalled that it was
> stopped.
> INFO   | jvm 1    | 2007/12/21 10:43:48 | WrapperManager Debug: Closing
> socket.
> DEBUG  | wrapperp | 2007/12/21 10:43:48 | socket read no code (closed?).
> DEBUG  | wrapperp | 2007/12/21 10:43:48 | server listening on port 32001.
> INFO   | jvm 1    | 2007/12/21 10:43:48 | WrapperManager Debug:
> ShutdownHook complete
> INFO   | jvm 1    | 2007/12/21 10:43:48 | WrapperManager Debug: Server
> daemon shut down
> ERROR  | wrapper  | 2007/12/21 10:44:06 | Shutdown failed: Timed out
> waiting for the JVM to terminate.
> ERROR  | wrapper  | 2007/12/21 10:44:07 | JVM did not exit on request,
> terminated
> DEBUG  | wrapper  | 2007/12/21 10:44:07 | Signal trapped.  Details:
> DEBUG  | wrapper  | 2007/12/21 10:44:07 |   signal number=17 (SIGCHLD),
> source="unknown"
> DEBUG  | wrapper  | 2007/12/21 10:44:07 | Received SIGCHLD, checking JVM
> process status.
> STATUS | wrapper  | 2007/12/21 10:44:07 | JVM received a signal SIGKILL
> (9).
> STATUS | wrapper  | 2007/12/21 10:44:07 | <-- Wrapper Stopped
> ---
>
> For this next run, I have extended the jvm_exit timeout long
> enough to allow the custom shutdown hook to complete.  It looks
> pretty much the same as the last example except that shutdown
> completes.
> ---
> DEBUG  | wrapperp | 2007/12/21 11:00:42 | read a packet STOP : 0
> DEBUG  | wrapper  | 2007/12/21 11:00:42 | JVM requested a shutdown. (0)
> DEBUG  | wrapper  | 2007/12/21 11:00:42 | wrapperStopProcess(0) called.
> DEBUG  | wrapper  | 2007/12/21 11:00:42 | Sending stop signal to JVM
> DEBUG  | wrapperp | 2007/12/21 11:00:42 | send a packet STOP : NULL
> INFO   | jvm 1    | 2007/12/21 11:00:42 | WrapperManager Debug: Received
> a packet STOP :
> INFO   | jvm 1    | 2007/12/21 11:00:43 | WrapperManager Debug: Thread,
> Wrapper-Shutdown-Hook, handling the shutdown process.
> INFO   | jvm 1    | 2007/12/21 11:00:43 | WrapperManager Debug: calling
> listener.stop()
> INFO   | jvm 1    | 2007/12/21 11:00:43 | WrapperSimpleApp Debug: stop(0)
> INFO   | jvm 1    | 2007/12/21 11:00:43 | WrapperManager Debug: returned
> from listener.stop() -> 0
> INFO   | jvm 1    | 2007/12/21 11:00:43 | WrapperManager Debug:
> shutdownJVM(0) Thread:Wrapper-Shutdown-Hook
> INFO   | jvm 1    | 2007/12/21 11:00:43 | WrapperManager Debug: Send a
> packet STOPPED : 0
> DEBUG  | wrapperp | 2007/12/21 11:00:43 | read a packet STOPPED : 0
> DEBUG  | wrapper  | 2007/12/21 11:00:43 | JVM signalled that it was
> stopped.
> INFO   | jvm 1    | 2007/12/21 11:00:44 | WrapperManager Debug: Closing
> socket.
> DEBUG  | wrapperp | 2007/12/21 11:00:44 | socket read no code (closed?).
> DEBUG  | wrapperp | 2007/12/21 11:00:44 | server listening on port 32001.
> INFO   | jvm 1    | 2007/12/21 11:00:44 | WrapperManager Debug:
> ShutdownHook complete
> INFO   | jvm 1    | 2007/12/21 11:00:44 | WrapperManager Debug: Server
> daemon shut down
> INFO   | jvm 1    | 2007/12/21 11:01:07 | Shutdown hook complete. Should
> exit now.
> DEBUG  | wrapper  | 2007/12/21 11:01:07 | JVM exited normally.
> DEBUG  | wrapper  | 2007/12/21 11:01:07 | Signal trapped.  Details:
> DEBUG  | wrapper  | 2007/12/21 11:01:07 |   signal number=17 (SIGCHLD),
> source="unknown"
> DEBUG  | wrapper  | 2007/12/21 11:01:07 | Received SIGCHLD, checking JVM
> process status.
> DEBUG  | wrapper  | 2007/12/21 11:01:07 | JVM process exited with a code
> of 0, leaving the wrapper exit code set to 0.
> STATUS | wrapper  | 2007/12/21 11:01:07 | <-- Wrapper Stopped
> ---
>
> In both of the above cases, the shutdown hook thread itself has
> its daemon flag set to false, the default.   I tried setting it to true
> to see what happened.   Normally a JVM does NOT wait for daemon
> threads to complete before exiting, I thought maybe the same
> might be true for shutdown hooks.  But the JVM seems to ignore
> the daemon flag for shutdown hooks.  It waited for my shutdown
> hook to complete regardless.
>
> The "Shutdown hook complete. Should exit now." message is also
> being displayed, so we know that the shutdown hook is not having
> any problems outputting to System.out.
>
> We should be able to get the shutdown hooks working correctly,
> but if not, a simpler option to your work around would be to
> make use of Integration Method 2, using the WrapperStartStopApp
> helper class.  You can configure that to always wait for the
> stop method to complete.  It does not rely on shutdown hooks.
>
> Also, as I appear to be having problems reproducing a problem that
> you are obviously able to easily reproduce, would it be possible for
> you to create a simple class running under the WrapperSimpleApp
> integration method that I can add to my test suite?
>
> Thanks,
> Leif
>
> Markus Schlegel wrote:
> > I think i am getting mad.
> > I've checked the whole code for System.exit() statements.
> > I've tested 1000 times, always with the same result that our
> > ShutdownHook does not finish.
> > I've also added a finally-clause in the shutdown hook, but even that
> > will not be executed (so there is no exception, the VM just exits).
> > I've also experimented with increasing the shutdown- and
> > jvm-exit-timeouts, but with no success.
> >
> > I've now changed our maintenance code. We no longer use a ShutdownHook
> > to cleanup and shutdown the services, since this seems not to work
> > reliable. Instead we register as a WrapperEventListener on startup and
> > trap all Control and ServiceControl Events that must lead in a
> > shutdown and perform our cleanup there in.
> > Because WrapperManager.restart() and WrapperManager.stop() do not fire
> > such events, I have to handle these cases additionally
> > (shutdown/restart performed from within our AdministrationClient).
> >
> > In our trunk, I would like to implement WrapperListener instead of
> > WrapperEventListener, but then I require some new License for our
> > 3.3-alpha release.
> >
> > Do you think this is a reasonable workaround?
> >
> > Markus
> >
> > 2007/12/19, Leif Mortenson <le...@ta...
> > <mailto:le...@ta...> >:
> >
> >     Markus,
> >     Looking at your log, the Wrapper is not doing anything special like
> >     killing the jvm process.  In that case, the JVM is handling the
> >     shutdown of the JVM.  The Wrapper simply calls System.exit in this
> >     case and runs its own shutdown hook to clean up after itself.
> >
> >     The JVM should be waiting for all normal shutdown hooks to
> >     complete before the JVM exits.  Are you certain that your JVM
> >     is not exiting due to an exception of some kind?  try adding a
> >     Try finally block and see if that code is getting run.
> >
> >     Cheers,
> >     Leif
> >
> >
> >
> >     Markus Schlegel wrote:
> >     > Hi
> >     > We have encountered a problem with service wrapper (3.2 and 3.3).
> >     > We use the WrapperSimpleApp as integration method. We have
> registred
> >     > our own Shutdown hook.
> >     > When we stop the service using the service mgmt console, some
> >     parts of
> >     > the Shutdown hook runs, but the vm is being terminated before the
> >     > shutdownhook is finished.
> >     > See the logfile using the debug-option:
> >     >
> >     > wrapper  | 2007/12/19 10:49:49 |   SERVICE_CONTROL_STOP
> >     > wrapper  | 2007/12/19 10:49:49 | wrapperStopProcess(0) called.
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: Received a
> >     > packet SERVICE_CONTROL_CODE : 1
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug:
> >     > ServiceControlCode from Wrapper with code 1
> >     > wrapper  | 2007/12/19 10:49:49 | Sending stop signal to JVM
> >     > wrapperp | 2007/12/19 10:49:49 | send a packet STOP : NULL
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: Received a
> >     > packet STOP :
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: Thread,
> >     > Wrapper-Connection, handling the shutdown process.
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: calling
> >     > listener.stop()
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: Waiting for
> >     > WrapperListener.stop runner thread to complete.
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug:
> >     > WrapperListener.stop runner thread started.
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperSimpleApp Debug: stop(0)
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug:
> >     > WrapperListener.stop runner thread stopped.
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: returned
> from
> >     > listener.stop() -> 0
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug:
> >     shutdownJVM(0)
> >     > Thread:Wrapper-Connection
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: Send a
> packet
> >     > STOPPED : 0
> >     > wrapperp | 2007/12/19 10:49:49 | read a packet STOPPED : 0
> >     > wrapper  | 2007/12/19 10:49:49 | JVM signalled that it was
> stopped.
> >     > jvm 1    | 2007/12/19 10:49:49 | WrapperManager Debug: Closing
> >     socket.
> >     > wrapperp | 2007/12/19 10:49:49 | socket read no code (closed?).
> >     > wrapperp | 2007/12/19 10:49:49 | server listening on port 32001.
> >     > jvm 1    | 2007/12/19 10:49:50 | WrapperManager Debug: calling
> >     > System.exit(0)
> >     >
> >     > -->this is our shutdown hook now
> >     >
> >     > jvm 1    | 2007/12/19 10:49:50 | (Log INFO): Shutdown hook called
> >     > jvm 1    | 2007/12/19 10:49:50 | (Log INFO): Stop Server
> >     > jvm 1    | 2007/12/19 10:49:50 | (Log INFO): Wenn der Server eine
> >     > grosse Anzahl Daten sichern muss, kann dies eine Weile dauern...
> >     > jvm 1    | 2007/12/19 10:49:50 | (Log INFO): All cabinets closed.
> >     > jvm 1    | 2007/12/19 10:49:50 | (Log INFO): Stop services...
> >     >
> >     > -->this was the last message of our shutdown hook, but there shuld
> >     > come more than that...
> >     >
> >     > wrapper  | 2007/12/19 10:49:50 | JVM process exited with a code
> >     of 0,
> >     > leaving the wrapper exit code set to 0.
> >     > wrapper  | 2007/12/19 10:49:50 | JVM exited normally.
> >     > wrapper  | 2007/12/19 10:49:50 | <-- Wrapper Stopped
> >     >
> >     >
> >     >
> >     >
> >     > It seems to me, that our Shutdown hook is interrupted by the
> >     exit of
> >     > the VM. Also the log is not always exactly the same, sometimes our
> >     > shutdown hook has no time to start running at all.
> >     > Is this exit of the VM caused by the wrapper?
> >     > Is this a bug?
> >     > I think the documentation on the website for integration method
> >     1 is
> >     > wrong when you look at the behavior above.
> >     >
> >     >
> >     >
> >     > Thanks
> >     > Markus
> >     >
> >
> ------------------------------------------------------------------------
> >     >
> >     >
> >
> -------------------------------------------------------------------------
> >
> >     > SF.Net email is sponsored by:
> >     > Check out the new SourceForge.net Marketplace.
> >     > It's the best place to buy or sell services
> >     > for just about anything Open Source.
> >     >
> >
> http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
> >     >
> >
> ------------------------------------------------------------------------
> >     >
> >     > _______________________________________________
> >     > Wrapper-user mailing list
> >     > Wra...@li...
> >     <mailto:Wra...@li...>
> >     > https://lists.sourceforge.net/lists/listinfo/wrapper-user
> >     <https://lists.sourceforge.net/lists/listinfo/wrapper-user>
> >     >
> >
> >
> >
> -------------------------------------------------------------------------
> >     SF.Net email is sponsored by:
> >     Check out the new SourceForge.net Marketplace.
> >     It's the best place to buy or sell services
> >     for just about anything Open Source.
> >
> http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
> >     _______________________________________________
> >     Wrapper-user mailing list
> >     Wra...@li...
> >     <mailto:Wra...@li...>
> >     https://lists.sourceforge.net/lists/listinfo/wrapper-user
> >     <https://lists.sourceforge.net/lists/listinfo/wrapper-user>
> >
> >
> > ------------------------------------------------------------------------
> >
> >
> -------------------------------------------------------------------------
> > SF.Net email is sponsored by:
> > Check out the new SourceForge.net Marketplace.
> > It's the best place to buy or sell services
> > for just about anything Open Source.
> >
> http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
> > ------------------------------------------------------------------------
> >
> > _______________________________________________
> > Wrapper-user mailing list
> > Wra...@li...
> > https://lists.sourceforge.net/lists/listinfo/wrapper-user
> >
>
>
> -------------------------------------------------------------------------
> This SF.net email is sponsored by: Microsoft
> Defy all challenges. Microsoft(R) Visual Studio 2005.
> http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>