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,
    I have been looking into this some more.  I added some more debug 
output to the
WrapperManager class to make it easier to debug this sort of problem.  
You can try
it from CVS if you like.  (SourceForge's public CVS is 24 hrs behind the 
dev archive)

    Looking over the debug log output that you sent me again, I noticed 
the following
line:

INFO   | jvm 7    | 2004/02/26 19:33:00 | Thread, WrapperSimpleAppMain, 
handling the shutdown process.

    This tells me that the WrapperSimpleApp helper class's main thread 
called
WrapperManager.stop.  This will happen if your class's main method throws an
uncaught exception.  Does that sound what might be happening?

    If this is the case then I would expect to have seen the following 
output in your log.
The log you posted was edited so you may have removed it.  Could you 
please confirm
one way or the other?

INFO   | jvm 7    | 2004/02/26 19:32:59 | WrapperSimpleApp: Encountered 
an error running main: (Your exception)

    If you are trying to invoke a restart on the above exception, it 
will not work because
the call to WrapperManager.stop will override the restart request and 
stop the Wrapper
along with its JVM.

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.
> ....