Re: [Wrapper-user] more on problems with filters- restart never works

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

I am actually seeing this same problem when it isn't an internal =20
exception in my code that would cause an exception.. but just when an =20=

out of memory exception happens...
which doesn't involve a system.exit anywhere in my code.

Here is a log from my testing last night:
----------------
INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:33 |

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:33 | WrapperSimpleApp: =
Encountered =20
an error running main: java.lang.OutOfMemoryError

STATUS | wrapper=A0| 2004/03/09 00:27:33 | Filter trigger =20
matched.=A0Restarting JVM.

DEBUG=A0| wrapper=A0| 2004/03/09 00:27:33 | wrapperRestartProcess() =
called.

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:33 | =
java.lang.OutOfMemoryError

STATUS | wrapper=A0| 2004/03/09 00:27:33 | Filter trigger =20
matched.=A0Restarting JVM.

DEBUG=A0| wrapper=A0| 2004/03/09 00:27:33 | wrapperRestartProcess() =20
called.=A0(IGNORED)

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:33 | Send a packet STOP : 0

DEBUG=A0| wrapperp | 2004/03/09 00:27:33 | read a packet STOP : 0

DEBUG=A0| wrapper=A0| 2004/03/09 00:27:33 | JVM requested a shutdown. =
(0)

DEBUG=A0| wrapper=A0| 2004/03/09 00:27:33 | wrapperStopProcess(0) =
called.

DEBUG=A0| wrapper=A0| 2004/03/09 00:27:33 | Sending stop signal to JVM

DEBUG=A0| wrapperp | 2004/03/09 00:27:33 | send a packet STOP : NULL

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:33 | Received a packet STOP =
:

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:34 | Thread, =
WrapperSimpleAppMain, =20
handling the shutdown process.

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:34 | calling =
listener.stop()

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:34 | WrapperSimpleApp: =
stop(0)

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:34 | returned from =
listener.stop()

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:34 | Send a packet STOPPED =
: 0

DEBUG=A0| wrapperp | 2004/03/09 00:27:34 | read a packet STOPPED : 0

DEBUG=A0| wrapper=A0| 2004/03/09 00:27:34 | JVM signalled that it was =20=

stopped.

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:34 | Closing socket.

DEBUG=A0| wrapperp | 2004/03/09 00:27:34 | socket read no code =
(closed?).

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:35 | calling System.exit(0)

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:35 | Server daemon shut =
down

INFO=A0=A0| jvm 4=A0=A0=A0| 2004/03/09 00:27:36 | AWTPATH C:\Program =20
Files\Java\j2re1.4.2_02\bin\jawt.dll

ERROR=A0| wrapper=A0| 2004/03/09 00:28:08 | Shutdown failed: Timed out =20=

waiting for the JVM to terminate.

ERROR=A0| wrapper=A0| 2004/03/09 00:28:08 | Java Virtual Machine did not =
=20
exit on request, terminated

STATUS | wrapper=A0| 2004/03/09 00:28:09 | <-- Wrapper Stopped

DEBUG=A0| wrapper=A0| 2004/03/09 00:28:09 | Exiting service process.
----------------
On Mar 8, 2004, at 11:12 AM, Jennifer Kolar wrote:

> I am not calling wrapper.stop anywhere.. I only call =
wrapper.restart();
> I do have some places in the code that issue System.exit(0) or =20
> System.exit(1)...however, I have ignore system events set....
>
> My one question here-- I remember reading that you said there was a =20=

> problem w/ restarts after a system.exit(1)..  and that you said that =20=

> was fixed
> in your current checked in code.. I am running from a build I did of =20=

> your code in CVS as of 3/1/04.
>
> I expect a System.exit(1) is being issued in these cases.. I will try =20=

> converting that in my internal code to use an exit code of 0.. I had =20=

> already made that change
> in the wrapperSimpleApp and saw no difference in behavior.
>
> is the system.exit(1) bug still lingering ??
>
> thanks
> Jennifer
> On Mar 6, 2004, at 6:34 AM, Leif Mortenson wrote:
>
>> Jennifer,
>>    Sorry to keep you waiting.  Busy week.
>>
>>    I tried this out and everything seems to be working correctly for =20=

>> me.  =46rom your log
>> output, it looks like restart triggers get fired several times in =20
>> rapid succession.  I tested
>> this and the Wrapper appears to be handling that correctly.  Once the =
=20
>> restart has
>> started, additional restart requests are correctly ignored.
>>
>>    I think the problem is the following lines from your output:
>> INFO   | jvm 7    | 2004/02/26 19:32:59 | Send a packet STOP : 0
>> DEBUG  | wrapperp | 2004/02/26 19:32:59 | read a packet STOP : 0
>> DEBUG  | wrapper  | 2004/02/26 19:32:59 | JVM requested a shutdown. =20=

>> (0)
>> DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperStopProcess(0) =20
>> called.
>>
>>    Are you sure you are not calling System.exit or =20
>> WrapperManager.stop() someplace
>> in your code?  If so that will override the restart request and cause =
=20
>> the Wrapper to
>> shutdown.
>>
>>    If you call System.exit, you will get the following in your log =20=

>> output.  System.exit
>> triggers a Shutdown Hook, which you have disabled, so I don't think =20=

>> this what is
>> happening:
>>
>> INFO   | jvm 1    | main    | 2004/03/06 23:27:15 | Wrapper Manager: =20=

>> ShutdownHook started
>> INFO   | jvm 1    | main    | 2004/03/06 23:27:15 | Send a packet =20
>> STOP : 0
>> DEBUG  | wrapperp | main    | 2004/03/06 23:27:15 | read a packet =20
>> STOP : 0
>> DEBUG  | wrapper  | main    | 2004/03/06 23:27:15 | JVM requested a =20=

>> shutdown. (0)
>> DEBUG  | wrapper  | main    | 2004/03/06 23:27:15 | =20
>> wrapperStopProcess(0) called.
>> DEBUG  | wrapper  | main    | 2004/03/06 23:27:15 | Sending stop =20
>> signal to JVM
>> DEBUG  | wrapperp | main    | 2004/03/06 23:27:15 | send a packet =20
>> STOP : NULL
>>
>>    A call you WrapperManager.stop(0) on the other hand, looks like =20=

>> the following.  This is
>> exactly what is showing up in your log:
>>
>> INFO   | jvm 1    | main    | 2004/03/06 23:29:06 | Send a packet =20
>> STOP : 0
>> DEBUG  | wrapperp | main    | 2004/03/06 23:29:06 | read a packet =20
>> STOP : 0
>> DEBUG  | wrapper  | main    | 2004/03/06 23:29:06 | JVM requested a =20=

>> shutdown. (0)
>> DEBUG  | wrapper  | main    | 2004/03/06 23:29:06 | =20
>> wrapperStopProcess(0) called.
>> DEBUG  | wrapper  | main    | 2004/03/06 23:29:06 | Sending stop =20
>> signal to JVM
>> DEBUG  | wrapperp | main    | 2004/03/06 23:29:06 | send a packet =20
>> STOP : NULL
>>
>>    Let me know if you don't think that is the cause or have questions =
=20
>> about to use
>> the filters.
>>
>> Cheers,
>> Leif
>>
>> Jennifer Kolar wrote:
>>
>>> Leif,
>>>
>>> It appears that I never have a successful FILTER based restart.  I =20=

>>> have no problem getting restarts when I call =20
>>> WrapperManager.restart() internally.. however--
>>> if there is an exception that I didn't catch that a filter matches, =20=

>>> then I never get a successful restart. I have had each of the =20
>>> following filters triggered always with the same result.
>>>
>>> I noticed that there was a recent email (Patrick Woodworth =20
>>> 1/23/2004)  where another person was having similiar problems and he =
=20
>>> found disabling the shutdown hooks to be a soln for him.. I've had =20=

>>> that disabled this whole time and  don't see any difference.
>>>
>>>
>>> Here are my filter settings from my conf file.
>>>
>>>     =20
>>> =
wrapper.filter.trigger.1=3Dcom.singingfish.werkflow.processors.Processo=20=

>>> rException
>>>     wrapper.filter.action.1=3DRESTART
>>>
>>>     wrapper.filter.trigger.2=3Djava.lang.Error
>>>     wrapper.filter.action.2=3DRESTART
>>>
>>>     wrapper.filter.trigger.3=3Djava.lang.OutOfMemoryError
>>>     wrapper.filter.action.3=3DRESTART
>>>
>>>
>>> I also have these set if it provides any help..  ( I have tried =20
>>> playing around w/ different startup timeouts and invocation times =20=

>>> and it seems to make no difference)
>>>
>>>     wrapper.jvm_exit.timeout=3D30
>>>     wrapper.cpu.timeout=3D10
>>>     wrapper.ping.timeout=3D300
>>>     wrapper.ping.interval=3D5
>>>     wrapper.restart.delay=3D1
>>>     wrapper.max_failed_invocations=3D3
>>>     wrapper.successful_invocation_time=3D10
>>>     wrapper.startup.timeout=3D30
>>>     wrapper.request_thread_dump_on_failed_jvm_exit=3DFALSE
>>>     wrapper.ignore_signals=3DTRUE
>>>     wrapper.disable_shutdown_hook=3DTRUE
>>>
>>> And again, here is the result I see whenever a filter is triggered:
>>>
>>>
>>> *STATUS | wrapper  | 2004/02/26 19:32:59 | Filter trigger matched.  =20=

>>> Restarting JVM.*
>>> *DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperRestartProcess() =20=

>>> called*
>>> ... (stuff from my stacktrack)
>>> *STATUS | wrapper  | 2004/02/26 19:32:59 | Filter trigger matched.  =20=

>>> Restarting JVM.*
>>> *DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperRestartProcess() =20=

>>> called.  (IGNORED)*
>>> INFO   | jvm 7    | 2004/02/26 19:32:59 | java.lang.Error: =20
>>> com.singingfish.werkflow.processors.ProcessorException: Unexpected =20=

>>> exception in cracker
>>> *STATUS | wrapper  | 2004/02/26 19:32:59 | Filter trigger matched.  =20=

>>> Restarting JVM.*
>>> *DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperRestartProcess() =20=

>>> called.  (IGNORED)*
>>> ... (stuff from my stack track)
>>> INFO   | jvm 7    | 2004/02/26 19:32:59 | Send a packet STOP : 0
>>> DEBUG  | wrapperp | 2004/02/26 19:32:59 | read a packet STOP : 0
>>> DEBUG  | wrapper  | 2004/02/26 19:32:59 | JVM requested a shutdown. =20=

>>> (0)
>>> DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperStopProcess(0) =20
>>> called.
>>> DEBUG  | wrapper  | 2004/02/26 19:32:59 | Sending stop signal to JVM
>>> DEBUG  | wrapperp | 2004/02/26 19:32:59 | send a packet STOP : NULL
>>> INFO   | jvm 7    | 2004/02/26 19:32:59 | Received a packet STOP :
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | Thread, =20
>>> WrapperSimpleAppMain, handling the shutdown process.
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | calling listener.stop()
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | WrapperSimpleApp: stop(0)
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | returned from =20
>>> listener.stop()
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | Send a packet STOPPED : 0
>>> DEBUG  | wrapperp | 2004/02/26 19:33:00 | read a packet STOPPED : 0
>>> DEBUG  | wrapper  | 2004/02/26 19:33:00 | JVM signalled that it was =20=

>>> stopped.
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | Closing socket.
>>> DEBUG  | wrapperp | 2004/02/26 19:33:00 | socket read no code =20
>>> (closed?).
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | calling System.exit(0)
>>> INFO   | jvm 7    | 2004/02/26 19:33:00 | Server daemon shut down
>>> DEBUG  | wrapper  | 2004/02/26 19:33:00 | JVM exited normally.
>>> STATUS | wrapper  | 2004/02/26 19:33:01 | <-- Wrapper Stopped
>>> STATUS | wrapper  | 2004/02/26 19:36:28 | CrackerAgent3 removed.
>>>
>>>
>>> in comparison-- a normal restart has the following ...
>>>
>>>
>>> INFO   | jvm 6    | 2004/02/26 19:31:48 | 2004-02-26 19:31:48,107 =20=

>>> DEBUG [WrapperSimpleAppMain] WerkflowAgent             - =20
>>> WerkflowEngine requested VM restart (null). Shutting down...
>>> INFO   | jvm 6    | 2004/02/26 19:31:48 | Send a packet RESTART : =20=

>>> restart
>>> DEBUG  | wrapperp | 2004/02/26 19:31:48 | read a packet RESTART : =20=

>>> restart
>>> STATUS | wrapper  | 2004/02/26 19:31:48 | JVM requested a restart.
>>> DEBUG  | wrapper  | 2004/02/26 19:31:48 | wrapperRestartProcess() =20=

>>> called.
>>> DEBUG  | wrapper  | 2004/02/26 19:31:48 | Sending stop signal to JVM
>>> DEBUG  | wrapperp | 2004/02/26 19:31:48 | send a packet STOP : NULL
>>> INFO   | jvm 6    | 2004/02/26 19:31:48 | Received a packet STOP :
>>> INFO   | jvm 6    | 2004/02/26 19:31:49 | Thread, =20
>>> WrapperSimpleAppMain, handling the shutdown process.
>>> INFO   | jvm 6    | 2004/02/26 19:31:49 | calling listener.stop()
>>> INFO   | jvm 6    | 2004/02/26 19:31:49 | WrapperSimpleApp: stop(0)
>>> INFO   | jvm 6    | 2004/02/26 19:31:49 | returned from =20
>>> listener.stop()
>>> INFO   | jvm 6    | 2004/02/26 19:31:49 | Send a packet STOPPED : 0
>>> DEBUG  | wrapperp | 2004/02/26 19:31:49 | read a packet STOPPED : 0
>>> DEBUG  | wrapper  | 2004/02/26 19:31:49 | JVM signalled that it was =20=

>>> stopped.
>>> INFO   | jvm 6    | 2004/02/26 19:31:49 | Closing socket.
>>> DEBUG  | wrapperp | 2004/02/26 19:31:49 | socket read no code =20
>>> (closed?).
>>> INFO   | jvm 6    | 2004/02/26 19:31:50 | calling System.exit(0)
>>> INFO   | jvm 6    | 2004/02/26 19:31:50 | Server daemon shut down
>>> DEBUG  | wrapper  | 2004/02/26 19:31:50 | JVM exited normally.
>>> STATUS | wrapper  | 2004/02/26 19:31:52 | Launching a JVM...
>>> DEBUG  | wrapper  | 2004/02/26 19:31:52 | command: =20
>>> "C:\WINNT\system32\java.exe" =20
>>> -Dcom.singingfish.core.utils.config.dir=3Dc:/sf/config =20
>>> -Duser.dir=3DC:\aolrun -Dsun.rmi.loader.logLevel=3DVERBOSE =20
>>> -Dsun.rmi.server.logLevel=3DVERBOSE =20
>>> -Dsun.rmi.transport.logLevel=3DVERBOSE =20
>>> -Dsun.rmi.transport.tcp.logLevel=3DVERBOSE =20
>>> -Dsun.rmi.transport.proxy.logLevel=3DVERBOSE -Xms3m -Xmx96m =20
>>> -Djava.library.path=3D"c:/sf/lib;c:/winnt;c:/winnt/system32;c:/=20
>>> j2sdk1.4.2_02/bin" -classpath =20
>>> "c:/sf/java/classes;c:/sf/java/jars/commons-logging-1.0.3/commons-=20=

>>> logging.jar;c:/sf/java/jars/jakarta-log4j-1.2.8/dist/lib/log4j=20
>>> -1.2.8.jar;c:/sf/java/jars/jakarta-oro-2.0.4/jakarta-oro-2.0.4.jar;=20=

>>> c:/sf/java/jars/quicktime_6_5/QTJava.zip;c:/sf/java/jars/xerces=20
>>> -1_3_1/xerces.jar;c:/sf/java/jars/toplink/TOPLink.jar;c:/sf/java/=20
>>> jars/toplink/Tools.jar;c:/sf/java/jars/toplink/TOPLinkX.jar;c:/sf/=20=

>>> java/jars/oracle_jdbc_9_2_03/ojdbc14.jar;c:/sf/java/jars/commons-=20
>>> httpclient-2.0/commons-httpclient-2.0-final.jar" =20
>>> -Dwrapper.key=3D"VRxfE5Fd856GSIaF" -Dwrapper.port=3D32013 =20
>>> -Dwrapper.debug=3D"TRUE" -Dwrapper.ignore_signals=3D"TRUE" =20
>>> -Dwrapper.service=3D"TRUE" -Dwrapper.disable_shutdown_hook=3D"TRUE" =20=

>>> -Dwrapper.cpu.timeout=3D"10" -Dwrapper.jvmid=3D7 =20
>>> org.tanukisoftware.wrapper.WrapperSimpleApp =20
>>> com.singingfish.werkflow.agent.WerkflowAgent =20
>>> c:/sf/config/workflow/specs/cracker.spec CrackerAgent3
>>> DEBUG  | wrapper  | 2004/02/26 19:31:52 | Java Virtual Machine =20
>>> started (PID=3D9244)
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Wrapper Manager: JVM #7
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Wrapper Manager: Using =20
>>> wrapper
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Calling native =20
>>> initialization method.
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Initializing =20
>>> WrapperManager native library.
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Java Executable: =20
>>> C:\WINNT\system32\java.exe
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Java Version   : =20
>>> 1.4.2_02-b03 Java HotSpot(TM) Client VM
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Java VM Vendor : Sun =20
>>> Microsystems Inc.
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 |
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Wrapper (Version 3.0.5)
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 |
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Open socket to wrapper =20
>>> attempted on port 32013...
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Opened Socket to port 3242
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | Send a packet KEY : =20
>>> VRxfE5Fd856GSIaF
>>> INFO   | jvm 7    | 2004/02/26 19:31:52 | =20
>>> handleSocket(Socket[addr=3D/127.0.0.1,port=3D32013,localport=3D3242])
>>> DEBUG  | wrapperp | 2004/02/26 19:31:52 | accepted a socket from =20
>>> 127.0.0.1 on port 3242
>>> DEBUG  | wrapperp | 2004/02/26 19:31:52 | read a packet KEY : =20
>>> VRxfE5Fd856GSIaF
>>> DEBUG  | wrapper  | 2004/02/26 19:31:52 | Got key from JVM: =20
>>> VRxfE5Fd856GSIaF
>>> DEBUG  | wrapperp | 2004/02/26 19:31:52 | send a packet =20
>>> LOW_LOG_LEVEL : 1
>>> DEBUG  | wrapperp | 2004/02/26 19:31:52 | send a packet PING_TIMEOUT =
=20
>>> : 300
>>> DEBUG  | wrapper  | 2004/02/26 19:31:52 | Start Application.
>>> ....
>>
>>
>>
>>
>> -------------------------------------------------------
>> This SF.Net email is sponsored by: IBM Linux Tutorials
>> Free Linux tutorial presented by Daniel Robbins, President and CEO of
>> GenToo technologies. Learn everything from fundamentals to system
>> administration.http://ads.osdn.com/?ad_id=3D1470&alloc_id=3D3638&op=3Dc=
lick
>> _______________________________________________
>> Wrapper-user mailing list
>> Wra...@li...
>> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>
>
>
> -------------------------------------------------------
> This SF.Net email is sponsored by: IBM Linux Tutorials
> Free Linux tutorial presented by Daniel Robbins, President and CEO of
> GenToo technologies. Learn everything from fundamentals to system
> administration.http://ads.osdn.com/?ad_id=3D1470&alloc_id=3D3638&op=3Dcl=
ick
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user