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

[Joseph A K. <jos...@tr...>]

Marsh, Ralph wrote:

> Joe, Thank you for your response. The Socket control details you
> provide are very useful.
> 
> However, since we started using it we have operated under the
> assumption that the Wrapper provides these kinds of services for
> recovering a dead JVM. If it does, I'm unaware how to configure it to
> do so. For example, can the Wrapper be configured to call
> ServerSocket.setReuseAddress(true) when it launches a JVM?

I rather doubt it, since the wrapper, if I'm not mistaken,
runs as a separate process from the JVM being managed.
The SO_REUSEADDRESS call must be made by the process that
attempts to re-bind the port in question (that is, your service's
JVM). Anyway, I think any experienced network programmer would
tell you that it's a network server's responsibility to handle
these sorts of issues.

There is (AFAIK) no easy way for the wrapper to know which
ports have been bound by the JVM that died. If the wrapper
had that information, it could bind new sockets to all those
ports and then close them cleanly, thus clearing the way for
the restarted JVM to bind them. Probably some clever person
could write a patch to do such a thing, but I don't think it
has been done yet.  Such code would almost certainly be OS-specific,
so it's not a trivial task.

(I should probably mention here that I haven't actually used
the wrapper in a couple of years; I just happen to still be
subscribed to the list.)

-- Joe

> Ralph
> 
> -----Original Message----- From:
> wra...@li... 
> [mailto:wra...@li...]On Behalf Of Joseph
> A Knapka Sent: Wednesday, April 06, 2005 1:19 PM To:
> wra...@li... Subject: Re: [Wrapper-user] Leif,
> please read: Tomcat NT JVM hung debug details
> 
> 
> Hi Ralph,
> 
> I have no idea if the Wrapper could be contributing to this problem,
> but:
> 
> Keep in mind that the TCP stack usually waits several minutes before
> releasing a port bound by a process that dies unexpectedly (this has
> to do with ensuring all the connection-closing activities involved in
> TCP are completed by the other end of the connection, I believe).  In
> the Unix socket API, you can specify an option called something like
> "SO_REUSEADDR" to force a new socket to bind to an in-use port. In
> Java, you can call ServerSocket.setReuseAddress(true) (before binding
> to an address!) to accomplish the same thing. You might give that a
> try.
> 
> Cheers,
> 
> -- Joe
> 
> 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
>>> 
>> 
>> 
>> 
>> ------------------------------------------------------- SF email is
>>  sponsored by - The IT Product Guide Read honest & candid reviews
>> on hundreds of IT Products from real users. Discover which products
>>  truly live up to the hype. Start reading now. 
>> http://ads.osdn.com/?ad_ide95&alloc_id396&op=ick 
>> _______________________________________________ Wrapper-user
>> mailing list Wra...@li... 
>> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>> 
>> 
>> ------------------------------------------------------- SF email is
>>  sponsored by - The IT Product Guide Read honest & candid reviews
>> on hundreds of IT Products from real users. Discover which products
>>  truly live up to the hype. Start reading now. 
>> http://ads.osdn.com/?ad_ide95&alloc_id396&op=click 
>> _______________________________________________ Wrapper-user
>> mailing list Wra...@li... 
>> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>> 
> 
> 
> 
> 
> ------------------------------------------------------- SF email is
> sponsored by - The IT Product Guide Read honest & candid reviews on
> hundreds of IT Products from real users. Discover which products
> truly live up to the hype. Start reading now. 
> http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click 
> _______________________________________________ Wrapper-user mailing
> list Wra...@li... 
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
> 
> 
> ------------------------------------------------------- SF email is
> sponsored by - The IT Product Guide Read honest & candid reviews on
> hundreds of IT Products from real users. Discover which products
> truly live up to the hype. Start reading now. 
> http://ads.osdn.com/?ad_ide95&alloc_id396&op=click 
> _______________________________________________ Wrapper-user mailing
> list Wra...@li... 
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>