Re: [Wrapper-user] Leif, please read: Tomcat NT JVM hung debug details

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

Ralph,
    Big apologies for the lack of a reply.  It was unfortunately not 
just to your questions.
There have been a lot of unanswered questions over the last couple 
months.  It is not
from a lack of interest but simply a complete and total lack of any free 
time as of late.
The Wrapper User mailing list has always consumes up to a couple hours a 
day of my
time.  In general I enjoy answering the questions and making the related 
changes to
the Wrapper.  But as of late even that time has not been there.
    I have been trying to check the list when I have a few minutes and 
then answer as
many questions, from newest going back, as I have time for.  Most likely 
you just never
fell into one of those sessions and got passed over.  Sorry about that.  
I understand that
it was probably frustrating. :-/   The goal is to get caught up and once 
again provide
a high level of support, hopefully soon.  I know it has also been way 
too long since
the last release. :-/

    Anyway, on to your question.

    On some platforms (Solaris) A port will remain bound for around 2 
minutes after
the application that bound the port shuts down.  From my past research 
this is to
handle any stray packets that may keep coming in from clients.
    As Joseph pointed out, this is not something that the Wrapper has 
any direct
control over.  Ideally you would rebind the port rather than doing a 
simple bind
when the application restarts.  This would require you to make some 
changes to
Tomcat however and is not ideal.

    A good workaround is for you to simply prevent the Wrapper from 
restarting
the JVM so quickly by adding a 2 minute delay between the first JVM shutting
down and the new JVM being launched.  You can do this with the following
property:
wrapper.restart.delay=130
http://wrapper.tanukisoftware.org/doc/english/prop-restart-delay.html

    I would suggest waiting slightly longer than the 2 minute bind 
timeout to make
sure that you don't have any sporadic errors, thus the 130 seconds.   
You should
play around with the timeout as you may be able to get things working with a
shorter delay.

    Thanks for the quality of your original question.  My bad for not 
getting around to it.

Cheers,
Leif

Marsh, Ralph wrote:

>Is this a difficult, stupid or uninteresting question I'm asking? I'm not accustomed to posting detailed descriptions of problems to lists multiple times (this is my 4th posting on this issue) and getting absolutely no response.
>
>If there is more detail required please let me know and I'll attempt to gather it. 
>
>I simply need a high level analysis of this situation to determine what if any contribution the wrapper has in this situation, either to help or to cause it. If it has no potential to cause the problem, I will move on. If it can be configured to help the problem please indicate how. Thank you.
>
>Ralph
>
>-----Original Message-----
>From: wra...@li...
>[mailto:wra...@li...]On Behalf Of Marsh,
>Ralph
>Sent: Friday, April 01, 2005 3:17 PM
>To: wra...@li...
>Subject: [Wrapper-user] Tomcat NT JVM hung debug details
>
>
>I ran the wrapper with log output set to DEBUG. The logs indicate that the wrapper detected what it thought was a hung JVM, attempted to launch a new JVM, had a problem binding to port 8081, then shutdown everything. This is my recurring problem. I'm including the debug output below. Questions:
>
>1) Is it possible the wrapper incorrectly identifies the JVM as hung?
>2) If so, how/why? Is there a timeout setting that can be increased to force the wrapper to attempt communication with the JVM longer before giving up?
>3) In the log "ERROR  | wrapper  | 2005/04/01 14:30:08 | Java Virtual Machine did not exit on request, terminated" appears. It seems the wrapper is attempting to stop that hung JVM before launching a new one. Does "terminated" mean the JVM or the wrapper action was terminated? If it's the JVM, why is port 8081 not released? If it's the wrapper, why can't the JVM be killed?
>4) in general, if the JVM is really hung, what can create this state?
>
>Bottom line: it appears the wrapper is trying to recover a JVM in a bad state but it is failing. Are there any configuration settings I can modify to help the wrapper successfully recover or initialize a JVM? Thanks.
>
>Ralph
>======================================
>DEBUG  | wrapperp | 2005/04/01 14:29:26 | send a packet PING : ping
>INFO   | jvm 1    | 2005/04/01 14:29:26 | Received a packet PING : ping
>INFO   | jvm 1    | 2005/04/01 14:29:26 | Send a packet PING : ok
>DEBUG  | wrapperp | 2005/04/01 14:29:26 | read a packet PING : ok
>DEBUG  | wrapper  | 2005/04/01 14:29:26 | Got ping response from JVM
>DEBUG  | wrapperp | 2005/04/01 14:29:32 | send a packet PING : ping
>INFO   | jvm 1    | 2005/04/01 14:29:32 | Received a packet PING : ping
>INFO   | jvm 1    | 2005/04/01 14:29:32 | Send a packet PING : ok
>DEBUG  | wrapperp | 2005/04/01 14:29:32 | read a packet PING : ok
>DEBUG  | wrapper  | 2005/04/01 14:29:32 | Got ping response from JVM
>DEBUG  | wrapperp | 2005/04/01 14:29:38 | send a packet PING : ping
>DEBUG  | wrapperp | 2005/04/01 14:29:44 | send a packet PING : ping
>DEBUG  | wrapperp | 2005/04/01 14:29:50 | send a packet PING : ping
>DEBUG  | wrapperp | 2005/04/01 14:29:56 | send a packet PING : ping
>DEBUG  | wrapperp | 2005/04/01 14:30:02 | send a packet PING : ping
>ERROR  | wrapper  | 2005/04/01 14:30:08 | JVM appears hung: Timed out waiting for signal from JVM.
>ERROR  | wrapper  | 2005/04/01 14:30:08 | Java Virtual Machine did not exit on request, terminated
>STATUS | wrapper  | 2005/04/01 14:30:14 | Launching a JVM...
>DEBUG  | wrapper  | 2005/04/01 14:30:14 | command: "C:\tools\j2sdk1.4.2\bin\java" -server -XX:+UseParNewGC -XX:MaxNewSize=24m -XX:NewSize=24m -XX:SurvivorRatio=128 -XX:+UseConcMarkSweepGC -XX:MaxTenuringThreshold=0 -XX:CMSInitiatingOccupancyFraction=60 -Djava.endorsed.dirs=../bin;../common/endorsed -Dcatalina.base=.. -Dcatalina.home=.. -Djava.io.tmpdir=../temp -Xms1200m -Xmx1200m -Djava.library.path="../common/lib" -classpath "../common/lib/wrapper.jar;C:\tools\j2sdk1.4.2/lib/tools.jar;../bin/bootstrap.jar" -Dwrapper.key="NhcjD9wi11JZ8IY8" -Dwrapper.port=32000 -Dwrapper.debug="TRUE" -Dwrapper.service="TRUE" -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=2 org.tanukisoftware.wrapper.WrapperStartStopApp org.apache.catalina.startup.Bootstrap 1 start org.apache.catalina.startup.Bootstrap true 1 stop
>DEBUG  | wrapper  | 2005/04/01 14:30:14 | Java Virtual Machine started (PID=6800)
>INFO   | jvm 2    | 2005/04/01 14:30:14 | Wrapper Manager: JVM #2
>INFO   | jvm 2    | 2005/04/01 14:30:14 | Wrapper Manager: Registering shutdown hook
>INFO   | jvm 2    | 2005/04/01 14:30:14 | Wrapper Manager: Using wrapper
>INFO   | jvm 2    | 2005/04/01 14:30:15 | Calling native initialization method.
>DEBUG  | wrapper  | 2005/04/01 14:30:15 | Pause reading child output to share cycles.
>DEBUG  | wrapperp | 2005/04/01 14:30:15 | accepted a socket from 127.0.0.1 on port 2035
>DEBUG  | wrapperp | 2005/04/01 14:30:15 | read a packet KEY : NhcjD9wi11JZ8IY8
>DEBUG  | wrapper  | 2005/04/01 14:30:15 | Got key from JVM: NhcjD9wi11JZ8IY8
>DEBUG  | wrapperp | 2005/04/01 14:30:15 | send a packet LOW_LOG_LEVEL : 1
>DEBUG  | wrapperp | 2005/04/01 14:30:15 | send a packet PING_TIMEOUT : 30
>DEBUG  | wrapper  | 2005/04/01 14:30:15 | Pause reading socket data to share cycles.
>DEBUG  | wrapper  | 2005/04/01 14:30:15 | Start Application.
>DEBUG  | wrapperp | 2005/04/01 14:30:15 | send a packet START : start
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Initializing WrapperManager native library.
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Java Executable: C:\tools\j2sdk1.4.2\bin\java.exe
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Java Version   : 1.4.2-b28 Java HotSpot(TM) Server VM
>DEBUG  | wrapper  | 2005/04/01 14:30:16 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Java VM Vendor : Sun Microsystems Inc.
>INFO   | jvm 2    | 2005/04/01 14:30:16 | 
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Wrapper (Version 3.0.5)
>DEBUG  | wrapper  | 2005/04/01 14:30:16 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:16 | 
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Open socket to wrapper...
>INFO   | jvm 2    | 2005/04/01 14:30:16 | Opened Socket
>DEBUG  | wrapper  | 2005/04/01 14:30:17 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:17 | Send a packet KEY : NhcjD9wi11JZ8IY8
>INFO   | jvm 2    | 2005/04/01 14:30:17 | handleSocket(Socket[addr=/127.0.0.1,port=32000,localport=2035])
>INFO   | jvm 2    | 2005/04/01 14:30:17 | Received a packet LOW_LOG_LEVEL : 1
>DEBUG  | wrapper  | 2005/04/01 14:30:17 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:17 | Wrapper Manager: LowLogLevel from Wrapper is 1
>INFO   | jvm 2    | 2005/04/01 14:30:17 | Received a packet PING_TIMEOUT : 30
>INFO   | jvm 2    | 2005/04/01 14:30:17 | Wrapper Manager: PingTimeout from Wrapper is 30000
>INFO   | jvm 2    | 2005/04/01 14:30:17 | Received a packet START : start
>INFO   | jvm 2    | 2005/04/01 14:30:17 | calling listener.start()
>INFO   | jvm 2    | 2005/04/01 14:30:17 | WrapperStartStopApp: start(args)
>INFO   | jvm 2    | 2005/04/01 14:30:17 | WrapperStartStopApp: invoking start main method
>DEBUG  | wrapper  | 2005/04/01 14:30:17 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:18 | WrapperStartStopApp: start(args) end.  Main Completed=false, exitCode=null
>INFO   | jvm 2    | 2005/04/01 14:30:18 | returned from listener.start()
>INFO   | jvm 2    | 2005/04/01 14:30:18 | Send a packet STARTED : 
>DEBUG  | wrapperp | 2005/04/01 14:30:18 | read a packet STARTED : 
>DEBUG  | wrapper  | 2005/04/01 14:30:18 | JVM signalled that it was started.
>DEBUG  | wrapperp | 2005/04/01 14:30:18 | send a packet PING : ping
>INFO   | jvm 2    | 2005/04/01 14:30:18 | Received a packet PING : ping
>INFO   | jvm 2    | 2005/04/01 14:30:18 | Send a packet PING : ok
>DEBUG  | wrapperp | 2005/04/01 14:30:18 | read a packet PING : ok
>DEBUG  | wrapper  | 2005/04/01 14:30:18 | Got ping response from JVM
>INFO   | jvm 2    | 2005/04/01 14:30:20 | StandardEngine[null]: setJvmRoute=tr2a
>INFO   | jvm 2    | 2005/04/01 14:30:20 | 2005-04-01 14:30:20,671 ERROR [] org.apache.coyote.http11.Http11Protocol.init:152 - Error initializing endpoint
>INFO   | jvm 2    | 2005/04/01 14:30:20 | java.net.BindException: Address already in use: JVM_Bind:8081
>INFO   | jvm 2    | 2005/04/01 14:30:20 | 	at org.apache.tomcat.util.net.PoolTcpEndpoint.initEndpoint(PoolTcpEndpoint.java:280)
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.coyote.http11.Http11Protocol.init(Http11Protocol.java:150)
>DEBUG  | wrapper  | 2005/04/01 14:30:21 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.coyote.tomcat4.CoyoteConnector.initialize(CoyoteConnector.java:1117)
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.catalina.core.StandardService.initialize(StandardService.java:579)
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.catalina.core.StandardServer.initialize(StandardServer.java:2246)
>DEBUG  | wrapper  | 2005/04/01 14:30:21 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.catalina.startup.Catalina.start(Catalina.java:511)
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.catalina.startup.Catalina.execute(Catalina.java:400)
>INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at org.apache.catalina.startup.Catalina.process(Catalina.java:180)
>DEBUG  | wrapper  | 2005/04/01 14:30:21 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>DEBUG  | wrapper  | 2005/04/01 14:30:22 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at java.lang.reflect.Method.invoke(Method.java:324)
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:203)
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>DEBUG  | wrapper  | 2005/04/01 14:30:22 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at java.lang.reflect.Method.invoke(Method.java:324)
>DEBUG  | wrapper  | 2005/04/01 14:30:22 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:126)
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at java.lang.Thread.run(Thread.java:534)
>INFO   | jvm 2    | 2005/04/01 14:30:23 | Catalina.start: LifecycleException:  Protocol handler initialization failed: java.net.BindException: Address already in use: JVM_Bind:8081
>INFO   | jvm 2    | 2005/04/01 14:30:23 | LifecycleException:  Protocol handler initialization failed: java.net.BindException: Address already in use: JVM_Bind:8081
>DEBUG  | wrapper  | 2005/04/01 14:30:23 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at org.apache.coyote.tomcat4.CoyoteConnector.initialize(CoyoteConnector.java:1119)
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at org.apache.catalina.core.StandardService.initialize(StandardService.java:579)
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at org.apache.catalina.core.StandardServer.initialize(StandardServer.java:2246)
>DEBUG  | wrapper  | 2005/04/01 14:30:23 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at org.apache.catalina.startup.Catalina.start(Catalina.java:511)
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at org.apache.catalina.startup.Catalina.execute(Catalina.java:400)
>INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at org.apache.catalina.startup.Catalina.process(Catalina.java:180)
>DEBUG  | wrapper  | 2005/04/01 14:30:23 | Pause reading child output to share cycles.
>DEBUG  | wrapperp | 2005/04/01 14:30:24 | send a packet PING : ping
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at java.lang.reflect.Method.invoke(Method.java:324)
>DEBUG  | wrapper  | 2005/04/01 14:30:24 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:203)
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>DEBUG  | wrapper  | 2005/04/01 14:30:24 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>INFO   | jvm 2    | 2005/04/01 14:30:25 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>DEBUG  | wrapper  | 2005/04/01 14:30:25 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:25 | 	at java.lang.reflect.Method.invoke(Method.java:324)
>INFO   | jvm 2    | 2005/04/01 14:30:25 | 	at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:126)
>INFO   | jvm 2    | 2005/04/01 14:30:25 | 	at java.lang.Thread.run(Thread.java:534)
>DEBUG  | wrapper  | 2005/04/01 14:30:25 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:25 | Catalina.stop: LifecycleException:  This server has not yet been started
>INFO   | jvm 2    | 2005/04/01 14:30:25 | Received a packet PING : ping
>DEBUG  | wrapper  | 2005/04/01 14:30:26 | Pause reading child output to share cycles.
>DEBUG  | wrapperp | 2005/04/01 14:30:26 | read a packet PING : ok
>DEBUG  | wrapper  | 2005/04/01 14:30:26 | Got ping response from JVM
>DEBUG  | wrapper  | 2005/04/01 14:30:26 | Pause reading socket data to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:26 | LifecycleException:  This server has not yet been started
>INFO   | jvm 2    | 2005/04/01 14:30:26 | Send a packet PING : ok
>INFO   | jvm 2    | 2005/04/01 14:30:26 | 	at org.apache.catalina.core.StandardServer.stop(StandardServer.java:2213)
>DEBUG  | wrapper  | 2005/04/01 14:30:26 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:26 | 	at org.apache.catalina.startup.Catalina.start(Catalina.java:543)
>INFO   | jvm 2    | 2005/04/01 14:30:26 | 	at org.apache.catalina.startup.Catalina.execute(Catalina.java:400)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at org.apache.catalina.startup.Catalina.process(Catalina.java:180)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>DEBUG  | wrapper  | 2005/04/01 14:30:27 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at java.lang.reflect.Method.invoke(Method.java:324)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:203)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>DEBUG  | wrapper  | 2005/04/01 14:30:27 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at java.lang.reflect.Method.invoke(Method.java:324)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:126)
>INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at java.lang.Thread.run(Thread.java:534)
>DEBUG  | wrapper  | 2005/04/01 14:30:27 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:28 | WrapperStartStopApp: start main method completed
>DEBUG  | wrapperp | 2005/04/01 14:30:30 | send a packet PING : ping
>INFO   | jvm 2    | 2005/04/01 14:30:30 | Received a packet PING : ping
>INFO   | jvm 2    | 2005/04/01 14:30:30 | Send a packet PING : ok
>INFO   | jvm 2    | 2005/04/01 14:30:30 | All non-daemon threads have stopped.  Exiting.
>DEBUG  | wrapper  | 2005/04/01 14:30:30 | Pause reading child output to share cycles.
>DEBUG  | wrapperp | 2005/04/01 14:30:30 | read a packet PING : ok
>DEBUG  | wrapper  | 2005/04/01 14:30:30 | Got ping response from JVM
>DEBUG  | wrapperp | 2005/04/01 14:30:31 | read a packet STOP : 0
>DEBUG  | wrapper  | 2005/04/01 14:30:31 | JVM requested a shutdown. (0)
>DEBUG  | wrapper  | 2005/04/01 14:30:31 | wrapperStopProcess(0) called.
>DEBUG  | wrapper  | 2005/04/01 14:30:31 | Pause reading socket data to share cycles.
>DEBUG  | wrapper  | 2005/04/01 14:30:31 | Sending stop signal to JVM
>DEBUG  | wrapperp | 2005/04/01 14:30:31 | send a packet STOP : NULL
>INFO   | jvm 2    | 2005/04/01 14:30:31 | Send a packet STOP : 0
>INFO   | jvm 2    | 2005/04/01 14:30:31 | Thread, Wrapper-Connection, handling the shutdown process.
>INFO   | jvm 2    | 2005/04/01 14:30:31 | calling listener.stop()
>DEBUG  | wrapper  | 2005/04/01 14:30:31 | Pause reading child output to share cycles.
>INFO   | jvm 2    | 2005/04/01 14:30:32 | WrapperStartStopApp: stop(0)
>INFO   | jvm 2    | 2005/04/01 14:30:32 | WrapperStartStopApp: invoking stop main method
>INFO   | jvm 2    | 2005/04/01 14:30:32 | WrapperStartStopApp: stop main method completed
>INFO   | jvm 2    | 2005/04/01 14:30:32 | returned from listener.stop()
>DEBUG  | wrapper  | 2005/04/01 14:30:32 | Pause reading child output to share cycles.
>DEBUG  | wrapperp | 2005/04/01 14:30:33 | read a packet STOPPED : 0
>DEBUG  | wrapper  | 2005/04/01 14:30:33 | JVM signalled that it was stopped.
>DEBUG  | wrapperp | 2005/04/01 14:30:33 | socket read no code (closed?).
>INFO   | jvm 2    | 2005/04/01 14:30:33 | Send a packet STOPPED : 0
>INFO   | jvm 2    | 2005/04/01 14:30:33 | Closing socket.
>INFO   | jvm 2    | 2005/04/01 14:30:33 | calling System.exit(0)
>DEBUG  | wrapper  | 2005/04/01 14:30:35 | JVM exited normally.
>STATUS | wrapper  | 2005/04/01 14:30:35 | <-- Wrapper Stopped
>  
>
>> -----Original Message-----
>>From: 	Marsh, Ralph  
>>Sent:	Friday, March 11, 2005 8:04 AM
>>To:	'wra...@li...'
>>Subject:	RE: Tomcat NT JVM hung
>>
>>Any suggestions in beginning to diagnose our problem would be appreciated. Thank you.
>>
>>	 -----Original Message-----
>>	From: 	Marsh, Ralph  
>>	Sent:	Thursday, March 03, 2005 4:18 PM
>>	To:	'wra...@li...'
>>	Subject:	Tomcat NT JVM hung
>>
>>	We are running a Struts web app on Tomcat 4.1. We use the wrapper to run Tomcat as a service.
>>
>>	Over the past 8 months, about once per month, the service has died. Within the past month the frequency of these events has gone up to about once per week. 
>>
>>	This leaves the web app dead in the water, the user receiving HTTP 500 errors and us logging into the NT box and manually restarting the service. We have the wrapper.conf file set to output STATUS level messages to the log. In the log we see this:
>>
>>	ERROR  | wrapper  | 2005/03/03 17:58:43 | JVM appears hung: Timed out waiting for signal from JVM.
>>	ERROR  | wrapper  | 2005/03/03 17:58:43 | Java Virtual Machine did not exit on request, terminated
>>	STATUS | wrapper  | 2005/03/03 17:58:49 | Launching a JVM...> 
>>	STATUS | wrapper  | 2005/03/03 17:59:03 | <-- Wrapper Stopped
>>
>>	I have four questions:
>>	1) what can cause a JVM backing Tomcat to hang?
>>	2) how should I configure the wrapper to get the most useful logging information during these events? Running in DEBUG for a week/weeks will produce copious logs. If necessary, I'll do it, but is it necessary?
>>	3) isn't the wrapper supposed to recognize these hangs, gracefully kill the process then restart a new process? If so, what should I look at to determine why this is not happening in our case
>>	4) in the log output above what is going on between the third and forth entry? It appears a new JVM is launching then the wrapper stops everything. Why?
>>
>>	Our complete wrapper.conf file is included below. Thank you.
>>
>>	Ralph Marsh
>>
>>	#********************************************************************
>>	# Wrapper Properties
>>	#********************************************************************
>>	# Java Application
>>	wrapper.java.command=%java_home%\bin\java
>>
>>	# Java Main class.  This class must implement the WrapperListener interface
>>	#  or guarantee that the WrapperManager class is initialized.  Helper
>>	#  classes are provided to do this for you.  See the Integration section
>>	#  of the documentation for details.
>>	wrapper.java.mainclass=org.tanukisoftware.wrapper.WrapperStartStopApp
>>
>>	# Java Classpath (include wrapper.jar)  Add class path elements as
>>	#  needed starting from 1
>>	wrapper.java.classpath.1=../common/lib/wrapper.jar
>>	wrapper.java.classpath.2=%java_home%/lib/tools.jar
>>	wrapper.java.classpath.3=../bin/bootstrap.jar
>>
>>	# Java Library Path (location of Wrapper.DLL or libwrapper.so)
>>	wrapper.java.library.path.1=../common/lib
>>
>>	# Java Additional Parameters
>>	wrapper.java.additional.1=-server
>>	wrapper.java.additional.2=-XX:+UseParNewGC
>>	wrapper.java.additional.3=-XX:MaxNewSize=24m
>>	wrapper.java.additional.4=-XX:NewSize=24m
>>	wrapper.java.additional.5=-XX:SurvivorRatio=128
>>	wrapper.java.additional.6=-XX:+UseConcMarkSweepGC
>>	wrapper.java.additional.7=-XX:MaxTenuringThreshold=0
>>	wrapper.java.additional.8=-XX:CMSInitiatingOccupancyFraction=60
>>	wrapper.java.additional.9=-Djava.endorsed.dirs=../bin;../common/endorsed
>>	wrapper.java.additional.10=-Dcatalina.base=..
>>	wrapper.java.additional.11=-Dcatalina.home=..
>>	wrapper.java.additional.12=-Djava.io.tmpdir=../temp
>>	                        
>>	#wrapper.java.additional.13=-verbosegc
>>	#wrapper.java.additional.14=-XX:+PrintGCTimeStamps
>>	#wrapper.java.additional.15=-XX:+PrintGCDetails
>>	#wrapper.java.additional.13=-XX:+PrintTenuringDistribution
>>
>>
>>	#wrapper.java.additional.7=-verbosegc
>>
>>	# Initial Java Heap Size (in MB)
>>	wrapper.java.initmemory=1200
>>
>>	# Maximum Java Heap Size (in MB)
>>	wrapper.java.maxmemory=1200
>>
>>	# Application parameters.  Add parameters as needed starting from 1
>>
>>	# The first application parameter is the name of the class whose main
>>	# method is to be called when the application is launched.  The class
>>	# name is followed by the number of parameters to be passed to its main
>>	# method.  Then comes the actual parameters.
>>	wrapper.app.parameter.1=org.apache.catalina.startup.Bootstrap
>>	wrapper.app.parameter.2=1
>>	wrapper.app.parameter.3=start
>>
>>	# The start parameters are followed by the name of the class whose main
>>	# method is to be called to stop the application.  The stop class name
>>	# is followed by a flag which controls whether or not the Wrapper should
>>	# wait for all non daemon threads to complete before exiting the JVM.
>>	# The flag is followed by the number of parameters to be passed to the
>>	# stop class's main method.  Finally comes the actual parameters.
>>	wrapper.app.parameter.4=org.apache.catalina.startup.Bootstrap
>>	wrapper.app.parameter.5=true
>>	wrapper.app.parameter.6=1
>>	wrapper.app.parameter.7=stop
>>
>>	#********************************************************************
>>	# Wrapper Logging Properties
>>	#********************************************************************
>>	# Format of output for the console.  (See docs for formats)
>>	wrapper.console.format=PM
>>
>>	# Log Level for console output.  (See docs for log levels)
>>	wrapper.console.loglevel=INFO
>>
>>	# Log file to use for wrapper output logging.
>>	wrapper.logfile=../logs/wrapper.log
>>
>>	# Format of output for the log file.  (See docs for formats)
>>	wrapper.logfile.format=LPTM
>>
>>	# Log Level for log file output.  (See docs for log levels)
>>	wrapper.logfile.loglevel=STATUS
>>
>>	# Maximum size that the log file will be allowed to grow to before
>>	#  the log is rolled. Size is specified in bytes.  The default value
>>	#  of 0, disables log rolling.  May abbreviate with the 'k' (kb) or
>>	#  'm' (mb) suffix.  For example: 10m = 10 megabytes.
>>	wrapper.logfile.maxsize=500k
>>
>>	# Maximum number of rolled log files which will be allowed before old
>>	#  files are deleted.  The default value of 0 implies no limit.
>>	wrapper.logfile.maxfiles=0
>>
>>	# Log Level for sys/event log output.  (See docs for log levels)
>>	wrapper.syslog.loglevel=NONE
>>
>>	#********************************************************************
>>	# Wrapper NT Service Properties
>>	#********************************************************************
>>	# WARNING - Do not modify any of these properties when an application
>>	#  using this configuration file has been installed as a service.
>>	#  Please uninstall the service before modifying this section.  The
>>	#  service can then be reinstalled.
>>
>>	# Name of the service
>>	wrapper.ntservice.name=tomcat-rights2a
>>
>>	# Display name of the service
>>	wrapper.ntservice.displayname=tomcat-rights2a
>>
>>	# Description of the service
>>	wrapper.ntservice.description=tomcat-rights2a
>>
>>	# Service dependencies.  Add dependencies as needed starting from 1
>>	wrapper.ntservice.dependency.1=
>>
>>	# Mode in which the service is installed.  AUTO_START or DEMAND_START
>>	wrapper.ntservice.starttype=AUTO_START
>>
>>	# Allow the service to interact with the desktop.
>>	wrapper.ntservice.interactive=false
>>
>>    
>>