Menu
▾
▴
wrapper-user
|
From: <TEI...@te...> - 2006-06-19 09:19:38
Attachments:
wrapper_agent.log
|
Hi! I tryed configuring the following variables with no results. The logging ou= tput is truncated right after the manager has finished. wrapper.shutdown.timeout=3D0 wrapper.jvm_exit.timeout=3D0 I attached a logfile. I can't get any clues from it, except that the wrappe= r seems to do its job. My question is, when does WrapperStartStopApp stop the service? Kind regards ----Mensaje original---- De: da...@sm... Recibido: 17/06/2006 6:09 Para: <wra...@li...> Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature= ly? (sorry for the personal post - stupid webmail client) You mention that your servers logging output is truncated. I guess =20 this means that your server was forceably closed by the Wrapper. This =20 normally happens when the wrapper has been notified of the stopping, =20 but the actual app has not stopped within the expected time period. =20 Check out the .conf property wrapper.shutdown.timeout or possibly =20 consider calling WrapperManager.signalStopping(...) every few seconds. To further get an understanding on what is going on under the bonnet, set t= he wrapper.debug to TRUE and inspect the results wrapper log file. This =20 will tell you exactly why the wrapper has shut down your application, =20 and will give you a better idea on how to solve it. You could post it as well for us to see if we could help. Cheers, Davy Boy Out... Quoting "TEI...@te..." <TEI...@te...>: > > Thanks, David! > > I don't think that's the case. I'll try to draw it with more =20 > detail. I developed my application without Wrapper in mind in the =20 > first > instance. Lets call the first app "Server" and "Manager" would be =20 > the second one. > Server is an event driven application, there's an event queue from =20 > where it pops events. When a "shutdown" event is read, Server stops > reading events, asks avery of its working threads (non daemon =20 > threads) to stop (they will close connections) and waits until all =20 > of them > have stopped (this doesn't take more than 5s). > Server logs almost every meaningful event/action it takes. > > The whole system, running alone, outside the wrapper, would log =20 > something like this. > > 1. Server: Start > 2. Server: Launching a "connector" thread to handle incoming connectio= ns. > 3. Server: Trying to connect to other applications (more threads =20 > and connections) > ... > 4. Server: Receiving an incoming connection -> a worker thread is =20 > launched in order to handle it. > ... > At this moment a number of (non daemon) threads are running. > ... > 5. Manager: Connected to the server, sent a shutdown command, =20 > closed connection and finish. > 6. Server: ( ... keeps doing its thing ...) A "shutdown" =20 > command/event was read. > 7. Server: Ask avery single thread to stop (threads will close =20 > connections as soon as possible). > 8. Server: Wait for every single thread to stop. > 9. Server: Finish > > The whole system, running into the wrapper > > 1. Server: Start > 2. Server: Launching a "connector" thread to handle incoming connectio= ns. > 3. Server: Trying to connect to other applications - more threads =20 > and connections > ... > 4. Server: Receiving an incoming connection -> a worker thread is =20 > launched in order to handle it. > ... > At this moment a number of (non daemon) threads are running. > ... > 5. Manager: Connected to the server, sent a shutdown command, =20 > closed connection and finish. > 6. Server: ( ... keeps doing its thing ...) A "shutdown" =20 > command/event was read. > At this moment Manager is already dead and WrapperStartStopApp =20 > seems has decided to kill Server too, cause logging output was > truncated > > I added a Thread.sleep(5000) to make sure Manager's death was =20 > after Server's, the resulting logging output was the same as if the =20 > system > were running alone, that is, not into WrapperStartStopApp. > > Further comments, please! > > > > Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, =20 > r=C3=A1pido, fiable. > > > > _______________________________________________ > Wrapper-user mailing list > Wra...@li... > https://lists.sourceforge.net/lists/listinfo/wrapper-user > _______________________________________________ Wrapper-user mailing list Wra...@li... https://lists.sourceforge.net/lists/listinfo/wrapper-user Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,= fiable. |
|
From: <TEI...@te...> - 2006-06-19 11:55:14
|
Hi, again!
Looking into WrapperStartStopApp I've noticed the 'stop' method is suppos=
ed to wait for all non-daemon threads to complete depending on=20
a boolean attribute called m_stopWait, which corresponds with the first par=
am passed to WrapperStartStopApp right after the shutdown class=20
param.
if ( m_stopWait )
{
int threadCnt;
while( ( threadCnt =3D WrapperManager.getNonDaemonThreadCou=
nt() ) > 1 )
{
if ( WrapperManager.isDebugEnabled() )
{
System.out.println( "WrapperStartStopApp: stopping.=
Waiting for "
+ (threadCnt - 1) + " threads to complete." );
}
try
{
Thread.sleep( 1000 );
}
catch ( InterruptedException e )
{
}
}
}
The logfile I sent in the previous mail was produced by Wrapper logging i=
n DEBUG level, so this sentence
- System.out.println( "WrapperStartStopApp: stopping. Waiting for "+ (=
threadCnt - 1) + " threads to complete." );
should have been executed, which wasn't the case.
I think I've configured WrapperStartStopApp properly so, perhaps, the ori=
gin of the problem might be when setting m_stopWait, or into=20
WrapperManager.getNonDaemonThreadCount()
What do you think?
=20
----Mensaje original----
De: TEI...@te...
Recibido: 19/06/2006 11:10
Para: <wra...@li...>
Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature=
ly?
Hi!
I tryed configuring the following variables with no results. The logging ou=
tput is truncated right after the manager has finished.
wrapper.shutdown.timeout=3D0
wrapper.jvm_exit.timeout=3D0
I attached a logfile. I can't get any clues from it, except that the wrappe=
r seems to do its job.
My question is, when does WrapperStartStopApp stop the service?
Kind regards
----Mensaje original----
De: da...@sm...
Recibido: 17/06/2006 6:09
Para: <wra...@li...>
Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature=
ly?
(sorry for the personal post - stupid webmail client)
You mention that your servers logging output is truncated. I guess =20
this means that your server was forceably closed by the Wrapper. This =20
normally happens when the wrapper has been notified of the stopping, =20
but the actual app has not stopped within the expected time period. =20
Check out the .conf property wrapper.shutdown.timeout or possibly =20
consider calling WrapperManager.signalStopping(...) every few seconds.
To further get an understanding on what is going on under the bonnet, set t=
he
wrapper.debug to TRUE and inspect the results wrapper log file. This =20
will tell you exactly why the wrapper has shut down your application, =20
and will give you a better idea on how to solve it.
You could post it as well for us to see if we could help.
Cheers,
Davy Boy Out...
Quoting "TEI...@te..." <TEI...@te...>:
>
> Thanks, David!
>
> I don't think that's the case. I'll try to draw it with more =20
> detail. I developed my application without Wrapper in mind in the =20
> first
> instance. Lets call the first app "Server" and "Manager" would be =20
> the second one.
> Server is an event driven application, there's an event queue from =20
> where it pops events. When a "shutdown" event is read, Server stops
> reading events, asks avery of its working threads (non daemon =20
> threads) to stop (they will close connections) and waits until all =20
> of them
> have stopped (this doesn't take more than 5s).
> Server logs almost every meaningful event/action it takes.
>
> The whole system, running alone, outside the wrapper, would log =20
> something like this.
>
> 1. Server: Start
> 2. Server: Launching a "connector" thread to handle incoming connectio=
ns.
> 3. Server: Trying to connect to other applications (more threads =20
> and connections)
> ...
> 4. Server: Receiving an incoming connection -> a worker thread is =20
> launched in order to handle it.
> ...
> At this moment a number of (non daemon) threads are running.
> ...
> 5. Manager: Connected to the server, sent a shutdown command, =20
> closed connection and finish.
> 6. Server: ( ... keeps doing its thing ...) A "shutdown" =20
> command/event was read.
> 7. Server: Ask avery single thread to stop (threads will close =20
> connections as soon as possible).
> 8. Server: Wait for every single thread to stop.
> 9. Server: Finish
>
> The whole system, running into the wrapper
>
> 1. Server: Start
> 2. Server: Launching a "connector" thread to handle incoming connectio=
ns.
> 3. Server: Trying to connect to other applications - more threads =20
> and connections
> ...
> 4. Server: Receiving an incoming connection -> a worker thread is =20
> launched in order to handle it.
> ...
> At this moment a number of (non daemon) threads are running.
> ...
> 5. Manager: Connected to the server, sent a shutdown command, =20
> closed connection and finish.
> 6. Server: ( ... keeps doing its thing ...) A "shutdown" =20
> command/event was read.
> At this moment Manager is already dead and WrapperStartStopApp =20
> seems has decided to kill Server too, cause logging output was
> truncated
>
> I added a Thread.sleep(5000) to make sure Manager's death was =20
> after Server's, the resulting logging output was the same as if the =20
> system
> were running alone, that is, not into WrapperStartStopApp.
>
> Further comments, please!
>
>
>
> Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, =20
> r=C3=A1pido, fiable.
>
>
>
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user
Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,=
fiable.
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user
Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,=
fiable.
|
|
From: <TEI...@te...> - 2006-06-19 14:04:21
|
I think I found the problem. I was finishing both Server and Manager with S=
ystem.exit(0) which caused the ShutdownHook to be called. This=20
happens before WrapperStartStopApp starts waiting for all non-daemon threa=
ds to terminate. Perhaps there's a configuration property=20
regarding this ...
----Mensaje original----
De: TEI...@te...
Recibido: 19/06/2006 13:55
Para: <wra...@li...>
Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature=
ly?
Hi, again!
Looking into WrapperStartStopApp I've noticed the 'stop' method is suppos=
ed to wait for all non-daemon threads to complete depending on=20
a boolean attribute called m_stopWait, which corresponds with the first par=
am passed to WrapperStartStopApp right after the shutdown=20
class=20
param.
if ( m_stopWait )
{
int threadCnt;
while( ( threadCnt =3D WrapperManager.getNonDaemonThreadCou=
nt() ) > 1 )
{
if ( WrapperManager.isDebugEnabled() )
{
System.out.println( "WrapperStartStopApp: stopping.=
Waiting for "
+ (threadCnt - 1) + " threads to complete." );
}
try
{
Thread.sleep( 1000 );
}
catch ( InterruptedException e )
{
}
}
}
The logfile I sent in the previous mail was produced by Wrapper logging i=
n DEBUG level, so this sentence
- System.out.println( "WrapperStartStopApp: stopping. Waiting for "+ (=
threadCnt - 1) + " threads to complete." );
should have been executed, which wasn't the case.
I think I've configured WrapperStartStopApp properly so, perhaps, the ori=
gin of the problem might be when setting m_stopWait, or into=20
WrapperManager.getNonDaemonThreadCount()
What do you think?
=20
----Mensaje original----
De: TEI...@te...
Recibido: 19/06/2006 11:10
Para: <wra...@li...>
Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature=
ly?
Hi!
I tryed configuring the following variables with no results. The logging ou=
tput is truncated right after the manager has finished.
wrapper.shutdown.timeout=3D0
wrapper.jvm_exit.timeout=3D0
I attached a logfile. I can't get any clues from it, except that the wrappe=
r seems to do its job.
My question is, when does WrapperStartStopApp stop the service?
Kind regards
----Mensaje original----
De: da...@sm...
Recibido: 17/06/2006 6:09
Para: <wra...@li...>
Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature=
ly?
(sorry for the personal post - stupid webmail client)
You mention that your servers logging output is truncated. I guess =20
this means that your server was forceably closed by the Wrapper. This =20
normally happens when the wrapper has been notified of the stopping, =20
but the actual app has not stopped within the expected time period. =20
Check out the .conf property wrapper.shutdown.timeout or possibly =20
consider calling WrapperManager.signalStopping(...) every few seconds.
To further get an understanding on what is going on under the bonnet, set t=
he
wrapper.debug to TRUE and inspect the results wrapper log file. This =20
will tell you exactly why the wrapper has shut down your application, =20
and will give you a better idea on how to solve it.
You could post it as well for us to see if we could help.
Cheers,
Davy Boy Out...
Quoting "TEI...@te..." <TEI...@te...>:
>
> Thanks, David!
>
> I don't think that's the case. I'll try to draw it with more =20
> detail. I developed my application without Wrapper in mind in the =20
> first
> instance. Lets call the first app "Server" and "Manager" would be =20
> the second one.
> Server is an event driven application, there's an event queue from =20
> where it pops events. When a "shutdown" event is read, Server stops
> reading events, asks avery of its working threads (non daemon =20
> threads) to stop (they will close connections) and waits until all =20
> of them
> have stopped (this doesn't take more than 5s).
> Server logs almost every meaningful event/action it takes.
>
> The whole system, running alone, outside the wrapper, would log =20
> something like this.
>
> 1. Server: Start
> 2. Server: Launching a "connector" thread to handle incoming connectio=
ns.
> 3. Server: Trying to connect to other applications (more threads =20
> and connections)
> ...
> 4. Server: Receiving an incoming connection -> a worker thread is =20
> launched in order to handle it.
> ...
> At this moment a number of (non daemon) threads are running.
> ...
> 5. Manager: Connected to the server, sent a shutdown command, =20
> closed connection and finish.
> 6. Server: ( ... keeps doing its thing ...) A "shutdown" =20
> command/event was read.
> 7. Server: Ask avery single thread to stop (threads will close =20
> connections as soon as possible).
> 8. Server: Wait for every single thread to stop.
> 9. Server: Finish
>
> The whole system, running into the wrapper
>
> 1. Server: Start
> 2. Server: Launching a "connector" thread to handle incoming connectio=
ns.
> 3. Server: Trying to connect to other applications - more threads =20
> and connections
> ...
> 4. Server: Receiving an incoming connection -> a worker thread is =20
> launched in order to handle it.
> ...
> At this moment a number of (non daemon) threads are running.
> ...
> 5. Manager: Connected to the server, sent a shutdown command, =20
> closed connection and finish.
> 6. Server: ( ... keeps doing its thing ...) A "shutdown" =20
> command/event was read.
> At this moment Manager is already dead and WrapperStartStopApp =20
> seems has decided to kill Server too, cause logging output was
> truncated
>
> I added a Thread.sleep(5000) to make sure Manager's death was =20
> after Server's, the resulting logging output was the same as if the =20
> system
> were running alone, that is, not into WrapperStartStopApp.
>
> Further comments, please!
>
>
>
> Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, =20
> r=C3=A1pido, fiable.
>
>
>
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user
Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,=
fiable.
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user
Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,=
fiable.
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user
Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,=
fiable.
|
|
From: Leif M. <le...@ta...> - 2006-06-19 14:36:33
|
Prueba,
It looks like you may have already figured this out. But here is
what is
happening. First the end of your log file and then I'll explain it to you.
INFO | jvm 1 | 2006/06/19 10:17:57 | [Manager (console)] Finished.
INFO | jvm 1 | 2006/06/19 10:17:57 | 34 mon 19/06/2006 10:17:57
[Manager] Finished.
INFO | jvm 1 | 2006/06/19 10:17:57 | Wrapper Manager: ShutdownHook
started
INFO | jvm 1 | 2006/06/19 10:17:57 | WrapperManager.stop(0) called
by thread: Wrapper-Shutdown-Hook
INFO | jvm 1 | 2006/06/19 10:17:57 | Thread, Wrapper-Shutdown-Hook,
waiting for the JVM to exit.
INFO | jvm 1 | 2006/06/19 10:18:02 | Thread, Wrapper-Shutdown-Hook,
continuing after 5 seconds.
INFO | jvm 1 | 2006/06/19 10:18:02 | Send a packet STOPPED : 0
DEBUG | wrapperp | 2006/06/19 10:18:02 | read a packet STOPPED : 0
DEBUG | wrapper | 2006/06/19 10:18:02 | JVM signalled that it was stopped.
INFO | jvm 1 | 2006/06/19 10:18:02 | Wrapper Manager: ShutdownHook
complete
DEBUG | wrapper | 2006/06/19 10:18:02 | JVM process exited with a code
of 0, leaving the wrapper exit code set to 0.
You see in the first few lines that after your Manager has sent the
shutdown command, and completes, the Wrapper's shutdown hook is immediately
being activated. This is most likely because your Manager class is calling
System.exit. In this mode, the original shutdown was triggered by the
Wrapper
and not by the JVM shutting down so the JVM has not yet started the
registered
shutdown hooks. It will do so now.
The Wrapper's shutdown hook is designed to block until the
WrapperListener.stop method has completed. When it calls System.exit, this
will never happen. To avoid a deadlock, the Wrapper is able to detect that
state and will only deadlock for a maximum of 5 seconds.
The JVM itself will exit as soon as all of its shutdown hooks have been
completed. It sounds like you are looping over your worker threads and
stopping each of them within a normal non daemon thread. The problem
is that none of that shutdown work is happening within the call stack of
a shutdown hook so the JVM is not going to wait for it all to complete
before shutting down.
You can solve this in one of two ways.
1) Remove the System.exit from your Manager shutdown process.
2) Add a shutdown hook to Server which loops until all of your worker
threads are stopped. That will keep the JVM up until it is safe to exit.
That would also make your Server application shutdown reliably when
it is running stand alone without the Wrapper and is killed with a CTRL-C.
I added the following note to the debug output for the next release.
The message will show up in the logs if the Wrapper's shutdown process
is initiated from within the WrapperListener.stop method by calling
System.exit.
---
System.exit appears to have been called from within the
WrapperListener.stop() method. If possible the application
should be modified to avoid this behavior.
To avoid a deadlock, this thread will only wait 5 seconds
for the application to shutdown. This may result in the
application failing to shutdown completely before the JVM
exists. Removing the offending System.exit call will
resolve this.
---
I also added a note about this to the documentation for the
WrapperStartStopApp.
Cheers,
Leif
TEI...@te... wrote:
> I think I found the problem. I was finishing both Server and Manager with System.exit(0) which caused the ShutdownHook to be called. This
> happens before WrapperStartStopApp starts waiting for all non-daemon threads to terminate. Perhaps there's a configuration property
> regarding this ...
>
|
|
From: <TEI...@te...> - 2006-06-19 15:21:58
|
Leif, I think that's exactly what was happening. I removed the System.exit =
call and then everything started to work as expected. The CTRL +=20
C feature is interesting, will take a look into that.
Many thanks to both David and Leif
teix
----Mensaje original----
De: le...@ta...
Recibido: 19/06/2006 16:36
Para: <TEI...@te...>, <wra...@li...>
Asunto: Re: [Wrapper-user] WrapperStartStopApp stopping service=09premature=
ly?
Prueba,
It looks like you may have already figured this out. But here is=20
what is
happening. First the end of your log file and then I'll explain it to you=
.
INFO | jvm 1 | 2006/06/19 10:17:57 | [Manager (console)] Finished.
INFO | jvm 1 | 2006/06/19 10:17:57 | 34 mon 19/06/2006 10:17:57=20
[Manager] Finished.
INFO | jvm 1 | 2006/06/19 10:17:57 | Wrapper Manager: ShutdownHook=20
started
INFO | jvm 1 | 2006/06/19 10:17:57 | WrapperManager.stop(0) called=20
by thread: Wrapper-Shutdown-Hook
INFO | jvm 1 | 2006/06/19 10:17:57 | Thread, Wrapper-Shutdown-Hook,=20
waiting for the JVM to exit.
INFO | jvm 1 | 2006/06/19 10:18:02 | Thread, Wrapper-Shutdown-Hook,=20
continuing after 5 seconds.
INFO | jvm 1 | 2006/06/19 10:18:02 | Send a packet STOPPED : 0
DEBUG | wrapperp | 2006/06/19 10:18:02 | read a packet STOPPED : 0
DEBUG | wrapper | 2006/06/19 10:18:02 | JVM signalled that it was stopped=
.
INFO | jvm 1 | 2006/06/19 10:18:02 | Wrapper Manager: ShutdownHook=20
complete
DEBUG | wrapper | 2006/06/19 10:18:02 | JVM process exited with a code=20
of 0, leaving the wrapper exit code set to 0.
You see in the first few lines that after your Manager has sent the
shutdown command, and completes, the Wrapper's shutdown hook is immediately
being activated. This is most likely because your Manager class is calling
System.exit. In this mode, the original shutdown was triggered by the=20
Wrapper
and not by the JVM shutting down so the JVM has not yet started the=20
registered
shutdown hooks. It will do so now.
The Wrapper's shutdown hook is designed to block until the
WrapperListener.stop method has completed. When it calls System.exit, this
will never happen. To avoid a deadlock, the Wrapper is able to detect tha=
t
state and will only deadlock for a maximum of 5 seconds.
The JVM itself will exit as soon as all of its shutdown hooks have been
completed. It sounds like you are looping over your worker threads and
stopping each of them within a normal non daemon thread. The problem
is that none of that shutdown work is happening within the call stack of
a shutdown hook so the JVM is not going to wait for it all to complete
before shutting down.
You can solve this in one of two ways.
1) Remove the System.exit from your Manager shutdown process.
2) Add a shutdown hook to Server which loops until all of your worker
threads are stopped. That will keep the JVM up until it is safe to exit.
That would also make your Server application shutdown reliably when
it is running stand alone without the Wrapper and is killed with a CTRL-C.
I added the following note to the debug output for the next release.
The message will show up in the logs if the Wrapper's shutdown process
is initiated from within the WrapperListener.stop method by calling
System.exit.
---
System.exit appears to have been called from within the
WrapperListener.stop() method. If possible the application
should be modified to avoid this behavior.
To avoid a deadlock, this thread will only wait 5 seconds
for the application to shutdown. This may result in the
application failing to shutdown completely before the JVM
exists. Removing the offending System.exit call will
resolve this.
---
I also added a note about this to the documentation for the
WrapperStartStopApp.
Cheers,
Leif
TEI...@te... wrote:
> I think I found the problem. I was finishing both Server and Manager with=
System.exit(0) which caused the ShutdownHook to be called.=20
This=20
> happens before WrapperStartStopApp starts waiting for all non-daemon thr=
eads to terminate. Perhaps there's a configuration property=20
> regarding this ...
> =20
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user
Prueba el correo Terra ( http://www.terra.es/correo ); Seguro, r=C3=A1pido,=
fiable.
|
