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

Jennifer,
    Sorry to keep you waiting.  Busy week.

    I tried this out and everything seems to be working correctly for 
me.  From your log
output, it looks like restart triggers get fired several times in rapid 
succession.  I tested
this and the Wrapper appears to be handling that correctly.  Once the 
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. (0)
DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperStopProcess(0) called.

    Are you sure you are not calling System.exit or 
WrapperManager.stop() someplace
in your code?  If so that will override the restart request and cause 
the Wrapper to
shutdown.

    If you call System.exit, you will get the following in your log 
output.  System.exit
triggers a Shutdown Hook, which you have disabled, so I don't think this 
what is
happening:

INFO   | jvm 1    | main    | 2004/03/06 23:27:15 | Wrapper Manager: 
ShutdownHook started
INFO   | jvm 1    | main    | 2004/03/06 23:27:15 | Send a packet STOP : 0
DEBUG  | wrapperp | main    | 2004/03/06 23:27:15 | read a packet STOP : 0
DEBUG  | wrapper  | main    | 2004/03/06 23:27:15 | JVM requested a 
shutdown. (0)
DEBUG  | wrapper  | main    | 2004/03/06 23:27:15 | 
wrapperStopProcess(0) called.
DEBUG  | wrapper  | main    | 2004/03/06 23:27:15 | Sending stop signal 
to JVM
DEBUG  | wrapperp | main    | 2004/03/06 23:27:15 | send a packet STOP : 
NULL

    A call you WrapperManager.stop(0) on the other hand, looks like 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 STOP : 0
DEBUG  | wrapperp | main    | 2004/03/06 23:29:06 | read a packet STOP : 0
DEBUG  | wrapper  | main    | 2004/03/06 23:29:06 | JVM requested a 
shutdown. (0)
DEBUG  | wrapper  | main    | 2004/03/06 23:29:06 | 
wrapperStopProcess(0) called.
DEBUG  | wrapper  | main    | 2004/03/06 23:29:06 | Sending stop signal 
to JVM
DEBUG  | wrapperp | main    | 2004/03/06 23:29:06 | send a packet STOP : 
NULL

    Let me know if you don't think that is the cause or have questions 
about to use
the filters.

Cheers,
Leif

Jennifer Kolar wrote:

> Leif,
>
> It appears that I never have a successful FILTER based restart.  I 
> have no problem getting restarts when I call WrapperManager.restart() 
> internally.. however--
> if there is an exception that I didn't catch that a filter matches, 
> then I never get a successful restart. I have had each of the 
> following filters triggered always with the same result.
>
> I noticed that there was a recent email (Patrick Woodworth 1/23/2004)  
> where another person was having similiar problems and he found 
> disabling the shutdown hooks to be a soln for him.. I've had that 
> disabled this whole time and  don't see any difference.
>
>
> Here are my filter settings from my conf file.
>
>     wrapper.filter.trigger.1=com.singingfish.werkflow.processors.ProcessorException
>     wrapper.filter.action.1=RESTART
>
>     wrapper.filter.trigger.2=java.lang.Error
>     wrapper.filter.action.2=RESTART
>
>     wrapper.filter.trigger.3=java.lang.OutOfMemoryError
>     wrapper.filter.action.3=RESTART
>
>
> I also have these set if it provides any help..  ( I have tried 
> playing around w/ different startup timeouts and invocation times and 
> it seems to make no difference)
>
>     wrapper.jvm_exit.timeout=30
>     wrapper.cpu.timeout=10
>     wrapper.ping.timeout=300
>     wrapper.ping.interval=5
>     wrapper.restart.delay=1
>     wrapper.max_failed_invocations=3
>     wrapper.successful_invocation_time=10
>     wrapper.startup.timeout=30
>     wrapper.request_thread_dump_on_failed_jvm_exit=FALSE
>     wrapper.ignore_signals=TRUE
>     wrapper.disable_shutdown_hook=TRUE
>
> And again, here is the result I see whenever a filter is triggered:
>
>
> *STATUS | wrapper  | 2004/02/26 19:32:59 | Filter trigger matched.  
> Restarting JVM.*
> *DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperRestartProcess() called*
> ... (stuff from my stacktrack)
> *STATUS | wrapper  | 2004/02/26 19:32:59 | Filter trigger matched.  
> Restarting JVM.*
> *DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperRestartProcess() 
> called.  (IGNORED)*
> INFO   | jvm 7    | 2004/02/26 19:32:59 | java.lang.Error: 
> com.singingfish.werkflow.processors.ProcessorException: Unexpected 
> exception in cracker
> *STATUS | wrapper  | 2004/02/26 19:32:59 | Filter trigger matched.  
> Restarting JVM.*
> *DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperRestartProcess() 
> 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. (0)
> DEBUG  | wrapper  | 2004/02/26 19:32:59 | wrapperStopProcess(0) 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, 
> 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 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 
> stopped.
> INFO   | jvm 7    | 2004/02/26 19:33:00 | Closing socket.
> DEBUG  | wrapperp | 2004/02/26 19:33:00 | socket read no code (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 
> DEBUG [WrapperSimpleAppMain] WerkflowAgent             - 
> WerkflowEngine requested VM restart (null). Shutting down...
> INFO   | jvm 6    | 2004/02/26 19:31:48 | Send a packet RESTART : restart
> DEBUG  | wrapperp | 2004/02/26 19:31:48 | read a packet RESTART : restart
> STATUS | wrapper  | 2004/02/26 19:31:48 | JVM requested a restart.
> DEBUG  | wrapper  | 2004/02/26 19:31:48 | wrapperRestartProcess() 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, 
> 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 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 
> stopped.
> INFO   | jvm 6    | 2004/02/26 19:31:49 | Closing socket.
> DEBUG  | wrapperp | 2004/02/26 19:31:49 | socket read no code (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: 
> "C:\WINNT\system32\java.exe" 
> -Dcom.singingfish.core.utils.config.dir=c:/sf/config 
> -Duser.dir=C:\aolrun -Dsun.rmi.loader.logLevel=VERBOSE 
> -Dsun.rmi.server.logLevel=VERBOSE -Dsun.rmi.transport.logLevel=VERBOSE 
> -Dsun.rmi.transport.tcp.logLevel=VERBOSE 
> -Dsun.rmi.transport.proxy.logLevel=VERBOSE -Xms3m -Xmx96m 
> -Djava.library.path="c:/sf/lib;c:/winnt;c:/winnt/system32;c:/j2sdk1.4.2_02/bin" 
> -classpath 
> "c:/sf/java/classes;c:/sf/java/jars/commons-logging-1.0.3/commons-logging.jar;c:/sf/java/jars/jakarta-log4j-1.2.8/dist/lib/log4j-1.2.8.jar;c:/sf/java/jars/jakarta-oro-2.0.4/jakarta-oro-2.0.4.jar;c:/sf/java/jars/quicktime_6_5/QTJava.zip;c:/sf/java/jars/xerces-1_3_1/xerces.jar;c:/sf/java/jars/toplink/TOPLink.jar;c:/sf/java/jars/toplink/Tools.jar;c:/sf/java/jars/toplink/TOPLinkX.jar;c:/sf/java/jars/oracle_jdbc_9_2_03/ojdbc14.jar;c:/sf/java/jars/commons-httpclient-2.0/commons-httpclient-2.0-final.jar" 
> -Dwrapper.key="VRxfE5Fd856GSIaF" -Dwrapper.port=32013 
> -Dwrapper.debug="TRUE" -Dwrapper.ignore_signals="TRUE" 
> -Dwrapper.service="TRUE" -Dwrapper.disable_shutdown_hook="TRUE" 
> -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=7 
> org.tanukisoftware.wrapper.WrapperSimpleApp 
> com.singingfish.werkflow.agent.WerkflowAgent 
> c:/sf/config/workflow/specs/cracker.spec CrackerAgent3
> DEBUG  | wrapper  | 2004/02/26 19:31:52 | Java Virtual Machine started 
> (PID=9244)
> 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 wrapper
> INFO   | jvm 7    | 2004/02/26 19:31:52 | Calling native 
> initialization method.
> INFO   | jvm 7    | 2004/02/26 19:31:52 | Initializing WrapperManager 
> native library.
> INFO   | jvm 7    | 2004/02/26 19:31:52 | Java Executable: 
> C:\WINNT\system32\java.exe
> INFO   | jvm 7    | 2004/02/26 19:31:52 | Java Version   : 
> 1.4.2_02-b03 Java HotSpot(TM) Client VM
> INFO   | jvm 7    | 2004/02/26 19:31:52 | Java VM Vendor : Sun 
> 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 
> 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 : 
> VRxfE5Fd856GSIaF
> INFO   | jvm 7    | 2004/02/26 19:31:52 | 
> handleSocket(Socket[addr=/127.0.0.1,port=32013,localport=3242])
> DEBUG  | wrapperp | 2004/02/26 19:31:52 | accepted a socket from 
> 127.0.0.1 on port 3242
> DEBUG  | wrapperp | 2004/02/26 19:31:52 | read a packet KEY : 
> VRxfE5Fd856GSIaF
> DEBUG  | wrapper  | 2004/02/26 19:31:52 | Got key from JVM: 
> VRxfE5Fd856GSIaF
> DEBUG  | wrapperp | 2004/02/26 19:31:52 | send a packet LOW_LOG_LEVEL : 1
> DEBUG  | wrapperp | 2004/02/26 19:31:52 | send a packet PING_TIMEOUT : 300
> DEBUG  | wrapper  | 2004/02/26 19:31:52 | Start Application.
> ....