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

How did you do your testcase? What OS do you use?
Could you send me your test-app in  order that I could test if it works the
same on our systems?

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
>