wrapper-user

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

[Marsh, R. <ral...@th...>]

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

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
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
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=3D24m -XX:NewSize=3D24m -XX:SurvivorRatio=3D128 =
-XX:+UseConcMarkSweepGC -XX:MaxTenuringThreshold=3D0 =
-XX:CMSInitiatingOccupancyFraction=3D60 =
-Djava.endorsed.dirs=3D../bin;../common/endorsed -Dcatalina.base=3D.. =
-Dcatalina.home=3D.. -Djava.io.tmpdir=3D../temp -Xms1200m -Xmx1200m =
-Djava.library.path=3D"../common/lib" -classpath =
"../common/lib/wrapper.jar;C:\tools\j2sdk1.4.2/lib/tools.jar;../bin/boots=
trap.jar" -Dwrapper.key=3D"NhcjD9wi11JZ8IY8" -Dwrapper.port=3D32000 =
-Dwrapper.debug=3D"TRUE" -Dwrapper.service=3D"TRUE" =
-Dwrapper.cpu.timeout=3D"10" -Dwrapper.jvmid=3D2 =
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=3D6800)
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 |=20
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 |=20
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=3D/127.0.0.1,port=3D32000,localport=3D2035])
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=3Dfalse, exitCode=3Dnull
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 :=20
DEBUG  | wrapperp | 2005/04/01 14:30:18 | read a packet STARTED :=20
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=3Dtr2a
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.j=
ava: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:22=
46)
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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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:22=
46)
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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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 =20
> Sent:	Friday, March 11, 2005 8:04 AM
> To:	'wra...@li...'
> Subject:	RE: Tomcat NT JVM hung
>=20
> Any suggestions in beginning to diagnose our problem would be =
appreciated. Thank you.
>=20
> 	 -----Original Message-----
> 	From: 	Marsh, Ralph =20
> 	Sent:	Thursday, March 03, 2005 4:18 PM
> 	To:	'wra...@li...'
> 	Subject:	Tomcat NT JVM hung
>=20
> 	We are running a Struts web app on Tomcat 4.1. We use the wrapper to =
run Tomcat as a service.
>=20
> 	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.=20
>=20
> 	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:
>=20
> 	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...>=20
> 	STATUS | wrapper  | 2005/03/03 17:59:03 | <-- Wrapper Stopped
>=20
> 	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?
>=20
> 	Our complete wrapper.conf file is included below. Thank you.
>=20
> 	Ralph Marsh
>=20
> 	#********************************************************************
> 	# Wrapper Properties
> 	#********************************************************************
> 	# Java Application
> 	wrapper.java.command=3D%java_home%\bin\java
>=20
> 	# 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=3Dorg.tanukisoftware.wrapper.WrapperStartStopApp
>=20
> 	# Java Classpath (include wrapper.jar)  Add class path elements as
> 	#  needed starting from 1
> 	wrapper.java.classpath.1=3D../common/lib/wrapper.jar
> 	wrapper.java.classpath.2=3D%java_home%/lib/tools.jar
> 	wrapper.java.classpath.3=3D../bin/bootstrap.jar
>=20
> 	# Java Library Path (location of Wrapper.DLL or libwrapper.so)
> 	wrapper.java.library.path.1=3D../common/lib
>=20
> 	# Java Additional Parameters
> 	wrapper.java.additional.1=3D-server
> 	wrapper.java.additional.2=3D-XX:+UseParNewGC
> 	wrapper.java.additional.3=3D-XX:MaxNewSize=3D24m
> 	wrapper.java.additional.4=3D-XX:NewSize=3D24m
> 	wrapper.java.additional.5=3D-XX:SurvivorRatio=3D128
> 	wrapper.java.additional.6=3D-XX:+UseConcMarkSweepGC
> 	wrapper.java.additional.7=3D-XX:MaxTenuringThreshold=3D0
> 	wrapper.java.additional.8=3D-XX:CMSInitiatingOccupancyFraction=3D60
> 	=
wrapper.java.additional.9=3D-Djava.endorsed.dirs=3D../bin;../common/endor=
sed
> 	wrapper.java.additional.10=3D-Dcatalina.base=3D..
> 	wrapper.java.additional.11=3D-Dcatalina.home=3D..
> 	wrapper.java.additional.12=3D-Djava.io.tmpdir=3D../temp
> 	                       =20
> 	#wrapper.java.additional.13=3D-verbosegc
> 	#wrapper.java.additional.14=3D-XX:+PrintGCTimeStamps
> 	#wrapper.java.additional.15=3D-XX:+PrintGCDetails
> 	#wrapper.java.additional.13=3D-XX:+PrintTenuringDistribution
>=20
>=20
> 	#wrapper.java.additional.7=3D-verbosegc
>=20
> 	# Initial Java Heap Size (in MB)
> 	wrapper.java.initmemory=3D1200
>=20
> 	# Maximum Java Heap Size (in MB)
> 	wrapper.java.maxmemory=3D1200
>=20
> 	# Application parameters.  Add parameters as needed starting from 1
>=20
> 	# 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=3Dorg.apache.catalina.startup.Bootstrap
> 	wrapper.app.parameter.2=3D1
> 	wrapper.app.parameter.3=3Dstart
>=20
> 	# 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=3Dorg.apache.catalina.startup.Bootstrap
> 	wrapper.app.parameter.5=3Dtrue
> 	wrapper.app.parameter.6=3D1
> 	wrapper.app.parameter.7=3Dstop
>=20
> 	#********************************************************************
> 	# Wrapper Logging Properties
> 	#********************************************************************
> 	# Format of output for the console.  (See docs for formats)
> 	wrapper.console.format=3DPM
>=20
> 	# Log Level for console output.  (See docs for log levels)
> 	wrapper.console.loglevel=3DINFO
>=20
> 	# Log file to use for wrapper output logging.
> 	wrapper.logfile=3D../logs/wrapper.log
>=20
> 	# Format of output for the log file.  (See docs for formats)
> 	wrapper.logfile.format=3DLPTM
>=20
> 	# Log Level for log file output.  (See docs for log levels)
> 	wrapper.logfile.loglevel=3DSTATUS
>=20
> 	# 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 =3D 10 megabytes.
> 	wrapper.logfile.maxsize=3D500k
>=20
> 	# 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=3D0
>=20
> 	# Log Level for sys/event log output.  (See docs for log levels)
> 	wrapper.syslog.loglevel=3DNONE
>=20
> 	#********************************************************************
> 	# 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.
>=20
> 	# Name of the service
> 	wrapper.ntservice.name=3Dtomcat-rights2a
>=20
> 	# Display name of the service
> 	wrapper.ntservice.displayname=3Dtomcat-rights2a
>=20
> 	# Description of the service
> 	wrapper.ntservice.description=3Dtomcat-rights2a
>=20
> 	# Service dependencies.  Add dependencies as needed starting from 1
> 	wrapper.ntservice.dependency.1=3D
>=20
> 	# Mode in which the service is installed.  AUTO_START or DEMAND_START
> 	wrapper.ntservice.starttype=3DAUTO_START
>=20
> 	# Allow the service to interact with the desktop.
> 	wrapper.ntservice.interactive=3Dfalse
>=20


-------------------------------------------------------
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_id=14396&op=3Dick
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user

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

[Marsh, R. <ral...@th...>]

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?

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.
>=20
> If there is more detail required please let me know and I'll attempt
> to gather it.
>=20
> 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.
>=20
> Ralph
>=20
> -----Original Message----- From:
> wra...@li...=20
> [mailto:wra...@li...]On Behalf Of Marsh,=20
> Ralph Sent: Friday, April 01, 2005 3:17 PM To:
> wra...@li... Subject: [Wrapper-user] Tomcat NT
> JVM hung debug details
>=20
>=20
> 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:
>=20
> 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?
>=20
> 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.
>=20
> Ralph =
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D 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=3D24m -XX:NewSize=3D24m
> -XX:SurvivorRatio=3D128 -XX:+UseConcMarkSweepGC
> -XX:MaxTenuringThreshold=3D0 -XX:CMSInitiatingOccupancyFraction=3D60
> -Djava.endorsed.dirs=3D../bin;../common/endorsed -Dcatalina.base=3D..
> -Dcatalina.home=3D.. -Djava.io.tmpdir=3D../temp -Xms1200m -Xmx1200m
> -Djava.library.path=3D"../common/lib" -classpath
> =
"../common/lib/wrapper.jar;C:\tools\j2sdk1.4.2/lib/tools.jar;../bin/boots=
trap.jar"
> -Dwrapper.key=3D"NhcjD9wi11JZ8IY8" -Dwrapper.port=3D32000
> -Dwrapper.debug=3D"TRUE" -Dwrapper.service=3D"TRUE"
> -Dwrapper.cpu.timeout=3D"10" -Dwrapper.jvmid=3D2
> 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=3D6800) 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.=20
> 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=20
> 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 |=20
> INFO   | jvm 2    | 2005/04/01 14:30:16 | Open socket to wrapper...=20
> 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=3D/127.0.0.1,port=3D32000,localport=3D2035]) =
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=3Dfalse,
> exitCode=3Dnull 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=3Dtr2a 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.j=
ava: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:22=
46)
>  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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.=20
> INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at
> =
org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.ja=
va: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:22=
46)
>  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(DelegatingMethodAccessorI=
mpl.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.=20
> 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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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.=20
> DEBUG  | wrapperp | 2005/04/01 14:30:26 | read a packet PING : ok=20
> DEBUG  | wrapper  | 2005/04/01 14:30:26 | Got ping response from JVM=20
> 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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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.=20
> DEBUG  | wrapperp | 2005/04/01 14:30:30 | read a packet PING : ok=20
> DEBUG  | wrapper  | 2005/04/01 14:30:30 | Got ping response from JVM=20
> DEBUG  | wrapperp | 2005/04/01 14:30:31 | read a packet STOP : 0=20
> 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
>=20
>> -----Original Message----- From: 	Marsh, Ralph Sent:	Friday, March
>> 11, 2005 8:04 AM To:	'wra...@li...' Subject:
>> RE: Tomcat NT JVM hung
>>=20
>> Any suggestions in beginning to diagnose our problem would be
>> appreciated. Thank you.
>>=20
>> -----Original Message----- From: 	Marsh, Ralph Sent:	Thursday,
>> March 03, 2005 4:18 PM To:	'wra...@li...'=20
>> Subject:	Tomcat NT JVM hung
>>=20
>> We are running a Struts web app on Tomcat 4.1. We use the wrapper
>> to run Tomcat as a service.
>>=20
>> 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.
>>=20
>> 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:
>>=20
>> 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...>=20
>> STATUS | wrapper  | 2005/03/03 17:59:03 | <-- Wrapper Stopped
>>=20
>> 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?
>>=20
>> Our complete wrapper.conf file is included below. Thank you.
>>=20
>> Ralph Marsh
>>=20
>> #********************************************************************
>>  # Wrapper Properties=20
>> #********************************************************************
>>  # Java Application wrapper.java.command=3D%java_home%\bin\java
>>=20
>> # 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.=20
>> =
wrapper.java.mainclass=3Dorg.tanukisoftware.wrapper.WrapperStartStopApp
>>=20
>>=20
>> # Java Classpath (include wrapper.jar)  Add class path elements as=20
>> #  needed starting from 1=20
>> wrapper.java.classpath.1=3D../common/lib/wrapper.jar=20
>> wrapper.java.classpath.2=3D%java_home%/lib/tools.jar=20
>> wrapper.java.classpath.3=3D../bin/bootstrap.jar
>>=20
>> # Java Library Path (location of Wrapper.DLL or libwrapper.so)=20
>> wrapper.java.library.path.1=3D../common/lib
>>=20
>> # Java Additional Parameters wrapper.java.additional.1=3D-server=20
>> wrapper.java.additional.2=3D-XX:+UseParNewGC=20
>> wrapper.java.additional.3=3D-XX:MaxNewSize=3D24m=20
>> wrapper.java.additional.4=3D-XX:NewSize=3D24m=20
>> wrapper.java.additional.5=3D-XX:SurvivorRatio=3D128=20
>> wrapper.java.additional.6=3D-XX:+UseConcMarkSweepGC=20
>> wrapper.java.additional.7=3D-XX:MaxTenuringThreshold=3D0=20
>> wrapper.java.additional.8=3D-XX:CMSInitiatingOccupancyFraction=3D60=20
>> =
wrapper.java.additional.9=3D-Djava.endorsed.dirs=3D../bin;../common/endor=
sed
>>  wrapper.java.additional.10=3D-Dcatalina.base=3D..=20
>> wrapper.java.additional.11=3D-Dcatalina.home=3D..=20
>> wrapper.java.additional.12=3D-Djava.io.tmpdir=3D../temp =20
>> #wrapper.java.additional.13=3D-verbosegc=20
>> #wrapper.java.additional.14=3D-XX:+PrintGCTimeStamps=20
>> #wrapper.java.additional.15=3D-XX:+PrintGCDetails=20
>> #wrapper.java.additional.13=3D-XX:+PrintTenuringDistribution
>>=20
>>=20
>> #wrapper.java.additional.7=3D-verbosegc
>>=20
>> # Initial Java Heap Size (in MB) wrapper.java.initmemory=3D1200
>>=20
>> # Maximum Java Heap Size (in MB) wrapper.java.maxmemory=3D1200
>>=20
>> # Application parameters.  Add parameters as needed starting from 1
>>=20
>>=20
>> # 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.=20
>> wrapper.app.parameter.1=3Dorg.apache.catalina.startup.Bootstrap=20
>> wrapper.app.parameter.2=3D1 wrapper.app.parameter.3=3Dstart
>>=20
>> # 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.=20
>> wrapper.app.parameter.4=3Dorg.apache.catalina.startup.Bootstrap=20
>> wrapper.app.parameter.5=3Dtrue wrapper.app.parameter.6=3D1=20
>> wrapper.app.parameter.7=3Dstop
>>=20
>> #********************************************************************
>>  # Wrapper Logging Properties=20
>> #********************************************************************
>>  # Format of output for the console.  (See docs for formats)=20
>> wrapper.console.format=3DPM
>>=20
>> # Log Level for console output.  (See docs for log levels)=20
>> wrapper.console.loglevel=3DINFO
>>=20
>> # Log file to use for wrapper output logging.=20
>> wrapper.logfile=3D../logs/wrapper.log
>>=20
>> # Format of output for the log file.  (See docs for formats)=20
>> wrapper.logfile.format=3DLPTM
>>=20
>> # Log Level for log file output.  (See docs for log levels)=20
>> wrapper.logfile.loglevel=3DSTATUS
>>=20
>> # Maximum size that the log file will be allowed to grow to before=20
>> #  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 =3D 10 megabytes.=20
>> wrapper.logfile.maxsize=3D500k
>>=20
>> # 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=3D0
>>=20
>> # Log Level for sys/event log output.  (See docs for log levels)=20
>> wrapper.syslog.loglevel=3DNONE
>>=20
>> #********************************************************************
>>  # Wrapper NT Service Properties=20
>> #********************************************************************
>>  # 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.
>>=20
>> # Name of the service wrapper.ntservice.name=3Dtomcat-rights2a
>>=20
>> # Display name of the service=20
>> wrapper.ntservice.displayname=3Dtomcat-rights2a
>>=20
>> # Description of the service=20
>> wrapper.ntservice.description=3Dtomcat-rights2a
>>=20
>> # Service dependencies.  Add dependencies as needed starting from 1
>>  wrapper.ntservice.dependency.1=3D
>>=20
>> # Mode in which the service is installed.  AUTO_START or
>> DEMAND_START wrapper.ntservice.starttype=3DAUTO_START
>>=20
>> # Allow the service to interact with the desktop.=20
>> wrapper.ntservice.interactive=3Dfalse
>>=20
>=20
>=20
>=20
> ------------------------------------------------------- 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.=20
> http://ads.osdn.com/?ad_ide95&alloc_id=14396&op=3Dick=20
> _______________________________________________ Wrapper-user mailing
> list Wra...@li...=20
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>=20
>=20
> ------------------------------------------------------- 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.=20
> http://ads.osdn.com/?ad_ide95&alloc_id=14396&op=3Dclick=20
> _______________________________________________ Wrapper-user mailing
> list Wra...@li...=20
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>=20



-------------------------------------------------------
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=3D6595&alloc_id=3D14396&op=3Dclick
_______________________________________________
Wrapper-user mailing list
Wrapper-user@lis...
 
[truncated message content]

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...
 
[truncated message content]

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

[Marsh, R. <ral...@th...>]

Joe,
A very helpful response. Thank you again.

Ralph

-----Original Message-----
From: wra...@li...
[mailto:wra...@li...]On Behalf Of Joseph A
Knapka
Sent: Wednesday, April 06, 2005 3:53 PM
To: wra...@li...
Subject: Re: [Wrapper-user] Leif, please read: Tomcat NT JVM hung debug
details


Marsh, Ralph wrote:

> Joe, Thank you for your response. The Socket control details you
> provide are very useful.
>=20
> 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
>=20
> -----Original Message----- From:
> wra...@li...=20
> [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
>=20
>=20
> Hi Ralph,
>=20
> I have no idea if the Wrapper could be contributing to this problem,
> but:
>=20
> 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.
>=20
> Cheers,
>=20
> -- Joe
>=20
> Marsh, Ralph wrote:
>=20
>=20
>> 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.
>>=20
>> If there is more detail required please let me know and I'll
>> attempt to gather it.
>>=20
>> I simply need a high level analysis of this situation to determine=20
>> 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.
>>=20
>> Ralph
>>=20
>> -----Original Message----- From:=20
>> wra...@li...=20
>> [mailto:wra...@li...]On Behalf Of
>> Marsh, Ralph Sent: Friday, April 01, 2005 3:17 PM To:=20
>> wra...@li... Subject: [Wrapper-user] Tomcat
>> NT JVM hung debug details
>>=20
>>=20
>> I ran the wrapper with log output set to DEBUG. The logs indicate=20
>> 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=20
>> shutdown everything. This is my recurring problem. I'm including
>> the debug output below. Questions:
>>=20
>> 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?
>>=20
>> 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.
>>=20
>> Ralph =
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D DEBUG  | wrapperp |=20
>> 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=3D24m -XX:NewSize=3D24m -XX:SurvivorRatio=3D128
>> -XX:+UseConcMarkSweepGC -XX:MaxTenuringThreshold=3D0
>> -XX:CMSInitiatingOccupancyFraction=3D60=20
>> -Djava.endorsed.dirs=3D../bin;../common/endorsed -Dcatalina.base=3D.. =

>> -Dcatalina.home=3D.. -Djava.io.tmpdir=3D../temp -Xms1200m -Xmx1200m=20
>> -Djava.library.path=3D"../common/lib" -classpath=20
>> =
"../common/lib/wrapper.jar;C:\tools\j2sdk1.4.2/lib/tools.jar;../bin/boots=
trap.jar"
>>  -Dwrapper.key=3D"NhcjD9wi11JZ8IY8" -Dwrapper.port=3D32000=20
>> -Dwrapper.debug=3D"TRUE" -Dwrapper.service=3D"TRUE"=20
>> -Dwrapper.cpu.timeout=3D"10" -Dwrapper.jvmid=3D2=20
>> org.tanukisoftware.wrapper.WrapperStartStopApp=20
>> org.apache.catalina.startup.Bootstrap 1 start=20
>> org.apache.catalina.startup.Bootstrap true 1 stop DEBUG  | wrapper
>> | 2005/04/01 14:30:14 | Java Virtual Machine started (PID=3D6800)
>> 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:=20
>> C:\tools\j2sdk1.4.2\bin\java.exe INFO   | jvm 2    | 2005/04/01=20
>> 14:30:16 | Java Version   : 1.4.2-b28 Java HotSpot(TM) Server VM=20
>> 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 |=20
>> handleSocket(Socket[addr=3D/127.0.0.1,port=3D32000,localport=3D2035])
>> 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=3Dfalse, exitCode=3Dnull 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=3Dtr2a INFO   | jvm 2    | 2005/04/01 14:30:20 |
>> 2005-04-01 14:30:20,671 ERROR []=20
>> org.apache.coyote.http11.Http11Protocol.init:152 - Error
>> initializing endpoint INFO   | jvm 2    | 2005/04/01 14:30:20 |=20
>> java.net.BindException: Address already in use: JVM_Bind:8081 INFO=20
>> | jvm 2    | 2005/04/01 14:30:20 | 	at=20
>> =
org.apache.tomcat.util.net.PoolTcpEndpoint.initEndpoint(PoolTcpEndpoint.j=
ava:280)
>>  INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at=20
>> 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=20
>> =
org.apache.coyote.tomcat4.CoyoteConnector.initialize(CoyoteConnector.java=
:1117)
>>  INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at=20
>> =
org.apache.catalina.core.StandardService.initialize(StandardService.java:=
579)
>>  INFO   | jvm 2    | 2005/04/01 14:30:21 | 	at=20
>> =
org.apache.catalina.core.StandardServer.initialize(StandardServer.java:22=
46)
>>  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=20
>> org.apache.catalina.startup.Catalina.execute(Catalina.java:400)
>> INFO | jvm 2    | 2005/04/01 14:30:21 | 	at=20
>> 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=20
>> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) INFO
>> | jvm 2    | 2005/04/01 14:30:22 | 	at=20
>> =
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=20
>> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI=
mpl.java:25)
>>  INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at=20
>> java.lang.reflect.Method.invoke(Method.java:324) INFO   | jvm 2
>> | 2005/04/01 14:30:22 | 	at=20
>> org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:203) INFO
>>  | jvm 2    | 2005/04/01 14:30:22 | 	at=20
>> 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=20
>> =
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java=
:39)
>>  INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at=20
>> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI=
mpl.java:25)
>>  INFO   | jvm 2    | 2005/04/01 14:30:22 | 	at=20
>> 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=20
>> =
org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.ja=
va:126)
>>  INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at=20
>> 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=20
>> =
org.apache.coyote.tomcat4.CoyoteConnector.initialize(CoyoteConnector.java=
:1119)
>>  INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at=20
>> =
org.apache.catalina.core.StandardService.initialize(StandardService.java:=
579)
>>  INFO   | jvm 2    | 2005/04/01 14:30:23 | 	at=20
>> =
org.apache.catalina.core.StandardServer.initialize(StandardServer.java:22=
46)
>>  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=20
>> org.apache.catalina.startup.Catalina.execute(Catalina.java:400)
>> INFO | jvm 2    | 2005/04/01 14:30:23 | 	at=20
>> 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=20
>> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) INFO
>> | jvm 2    | 2005/04/01 14:30:24 | 	at=20
>> =
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java=
:39)
>>  INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at=20
>> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI=
mpl.java:25)
>>  INFO   | jvm 2    | 2005/04/01 14:30:24 | 	at=20
>> 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=20
>> org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:203) INFO
>>  | jvm 2    | 2005/04/01 14:30:24 | 	at=20
>> 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=20
>> =
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java=
:39)
>>  INFO   | jvm 2    | 2005/04/01 14:30:25 | 	at=20
>> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI=
mpl.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=20
>> =
org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.ja=
va:126)
>>  INFO   | jvm 2    | 2005/04/01 14:30:25 | 	at=20
>> 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=20
>> =
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=20
>> org.apache.catalina.startup.Catalina.execute(Catalina.java:400)
>> INFO | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> org.apache.catalina.startup.Catalina.process(Catalina.java:180)
>> INFO | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) INFO
>> | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> =
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java=
:39)
>>  INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI=
mpl.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=20
>> org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:203) INFO
>>  | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) INFO
>> | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> =
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=20
>> =
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorI=
mpl.java:25)
>>  INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> java.lang.reflect.Method.invoke(Method.java:324) INFO   | jvm 2
>> | 2005/04/01 14:30:27 | 	at=20
>> =
org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.ja=
va:126)
>>  INFO   | jvm 2    | 2005/04/01 14:30:27 | 	at=20
>> 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
>>=20
>>=20
>>> -----Original Message----- From: 	Marsh, Ralph Sent:	Friday,
>>> March 11, 2005 8:04 AM To:	'wra...@li...'
>>> Subject: RE: Tomcat NT JVM hung
>>>=20
>>> Any suggestions in beginning to diagnose our problem would be=20
>>> appreciated. Thank you.
>>>=20
>>> -----Original Message----- From: 	Marsh, Ralph Sent:	Thursday,=20
>>> March 03, 2005 4:18 PM To:	'wra...@li...'=20
>>> Subject:	Tomcat NT JVM hung
>>>=20
>>> We are running a Struts web app on Tomcat 4.1. We use the wrapper
>>>  to run Tomcat as a service.
>>>=20
>>> 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.
>>>=20
>>> 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:
>>>=20
>>> ERROR  | wrapper  | 2005/03/03 17:58:43 | JVM appears hung: Timed
>>>  out waiting for signal from JVM. ERROR  | wrapper  | 2005/03/03=20
>>> 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
>>>=20
>>> I have four questions: 1) what can cause a JVM backing Tomcat to=20
>>> 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?
>>>=20
>>> Our complete wrapper.conf file is included below. Thank you.
>>>=20
>>> Ralph Marsh
>>>=20
>>> =
#********************************************************************
>>>  # Wrapper Properties=20
>>> =
#********************************************************************
>>>  # Java Application wrapper.java.command=3D%java_home%\bin\java
>>>=20
>>> # Java Main class.  This class must implement the WrapperListener
>>>  interface #  or guarantee that the WrapperManager class is=20
>>> initialized.  Helper #  classes are provided to do this for you.=20
>>> See the Integration section #  of the documentation for details.
>>> =20
>>> =
wrapper.java.mainclass=3Dorg.tanukisoftware.wrapper.WrapperStartStopApp
>>>=20
>>>=20
>>>=20
>>> # Java Classpath (include wrapper.jar)  Add class path elements
>>> as #  needed starting from 1=20
>>> wrapper.java.classpath.1=3D../common/lib/wrapper.jar=20
>>> wrapper.java.classpath.2=3D%java_home%/lib/tools.jar=20
>>> wrapper.java.classpath.3=3D../bin/bootstrap.jar
>>>=20
>>> # Java Library Path (location of Wrapper.DLL or libwrapper.so)=20
>>> wrapper.java.library.path.1=3D../common/lib
>>>=20
>>> # Java Additional Parameters wrapper.java.additional.1=3D-server=20
>>> wrapper.java.additional.2=3D-XX:+UseParNewGC=20
>>> wrapper.java.additional.3=3D-XX:MaxNewSize=3D24m=20
>>> wrapper.java.additional.4=3D-XX:NewSize=3D24m=20
>>> wrapper.java.additional.5=3D-XX:SurvivorRatio=3D128=20
>>> wrapper.java.additional.6=3D-XX:+UseConcMarkSweepGC=20
>>> wrapper.java.additional.7=3D-XX:MaxTenuringThreshold=3D0=20
>>> wrapper.java.additional.8=3D-XX:CMSInitiatingOccupancyFraction=3D60=20
>>> =
wrapper.java.additional.9=3D-Djava.endorsed.dirs=3D../bin;../common/endor=
sed
>>>  wrapper.java.additional.10=3D-Dcatalina.base=3D..=20
>>> wrapper.java.additional.11=3D-Dcatalina.home=3D..=20
>>> wrapper.java.additional.12=3D-Djava.io.tmpdir=3D../temp=20
>>> #wrapper.java.additional.13=3D-verbosegc=20
>>> #wrapper.java.additional.14=3D-XX:+PrintGCTimeStamps=20
>>> #wrapper.java.additional.15=3D-XX:+PrintGCDetails=20
>>> #wrapper.java.additional.13=3D-XX:+PrintTenuringDistribution
>>>=20
>>>=20
>>> #wrapper.java.additional.7=3D-verbosegc
>>>=20
>>> # Initial Java Heap Size (in MB) wrapper.java.initmemory=3D1200
>>>=20
>>> # Maximum Java Heap Size (in MB) wrapper.java.maxmemory=3D1200
>>>=20
>>> # Application parameters.  Add parameters as needed starting from
>>> 1
>>>=20
>>>=20
>>> # The first application parameter is the name of the class whose=20
>>> main # method is to be called when the application is launched.=20
>>> The class # name is followed by the number of parameters to be=20
>>> passed to its main # method.  Then comes the actual parameters.=20
>>> wrapper.app.parameter.1=3Dorg.apache.catalina.startup.Bootstrap=20
>>> wrapper.app.parameter.2=3D1 wrapper.app.parameter.3=3Dstart
>>>=20
>>> # 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.=20
>>> wrapper.app.parameter.4=3Dorg.apache.catalina.startup.Bootstrap=20
>>> wrapper.app.parameter.5=3Dtrue wrapper.app.parameter.6=3D1=20
>>> wrapper.app.parameter.7=3Dstop
>>>=20
>>> =
#********************************************************************
>>>  # Wrapper Logging Properties=20
>>> =
#********************************************************************
>>>  # Format of output for the console.  (See docs for formats)=20
>>> wrapper.console.format=3DPM
>>>=20
>>> # Log Level for console output.  (See docs for log levels)=20
>>> wrapper.console.loglevel=3DINFO
>>>=20
>>> # Log file to use for wrapper output logging.=20
>>> wrapper.logfile=3D../logs/wrapper.log
>>>=20
>>> # Format of output for the log file.  (See docs for formats)=20
>>> wrapper.logfile.format=3DLPTM
>>>=20
>>> # Log Level for log file output.  (See docs for log levels)=20
>>> wrapper.logfile.loglevel=3DSTATUS
>>>=20
>>> # 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 =3D 10
>>> megabytes. wrapper.logfile.maxsize=3D500k
>>>=20
>>> # 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=3D0
>>>=20
>>> # Log Level for sys/event log output.  (See docs for log levels)
>>>  wrapper.syslog.loglevel=3DNONE
>>>=20
>>> =
#********************************************************************
>>>  # Wrapper NT Service Properties=20
>>> =
#********************************************************************
>>>  # WARNING - Do not modify any of these properties when an=20
>>> application #  using this configuration file has been instal...
 
[truncated message content]

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

[Marsh, R. <ral...@th...>]

Thank you Leif. I'll play with the delay setting. While I try to figure =
out why the JVM keeps dying.

-----Original Message-----
From: wra...@li...
[mailto:wra...@li...]On Behalf Of Leif
Mortenson
Sent: Tuesday, April 12, 2005 12:25 AM
To: wra...@li...
Subject: Re: [Wrapper-user] Leif, please read: Tomcat NT JVM hung debug
details


Ralph,
    Big apologies for the lack of a reply.  It was unfortunately not=20
just to your questions.
There have been a lot of unanswered questions over the last couple=20
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=20
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=20
too long since
the last release. :-/

    Anyway, on to your question.

    On some platforms (Solaris) A port will remain bound for around 2=20
minutes after
the application that bound the port shuts down.  From my past research=20
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=20
any direct
control over.  Ideally you would rebind the port rather than doing a=20
simple bind
when the application restarts.  This would require you to make some=20
changes to
Tomcat however and is not ideal.

    A good workaround is for you to simply prevent the Wrapper from=20
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=3D130
http://wrapper.tanukisoftware.org/doc/english/prop-restart-delay.html

    I would suggest waiting slightly longer than the 2 minute bind=20
timeout to make
sure that you don't have any sporadic errors, thus the 130 seconds.  =20
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=20
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.=20
>
>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
>=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>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=3D24m -XX:NewSize=3D24m -XX:SurvivorRatio=3D128 =
-XX:+UseConcMarkSweepGC -XX:MaxTenuringThreshold=3D0 =
-XX:CMSInitiatingOccupancyFraction=3D60 =
-Djava.endorsed.dirs=3D../bin;../common/endorsed -Dcatalina.base=3D.. =
-Dcatalina.home=3D.. -Djava.io.tmpdir=3D../temp -Xms1200m -Xmx1200m =
-Djava.library.path=3D"../common/lib" -classpath =
"../common/lib/wrapper.jar;C:\tools\j2sdk1.4.2/lib/tools.jar;../bin/boots=
trap.jar" -Dwrapper.key=3D"NhcjD9wi11JZ8IY8" -Dwrapper.port=3D32000 =
-Dwrapper.debug=3D"TRUE" -Dwrapper.service=3D"TRUE" =
-Dwrapper.cpu.timeout=3D"10" -Dwrapper.jvmid=3D2 =
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=3D6800)
>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 |=20
>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 |=20
>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=3D/127.0.0.1,port=3D32000,localport=3D2035])
>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=3Dfalse, exitCode=3Dnull
>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 :=20
>DEBUG  | wrapperp | 2005/04/01 14:30:18 | read a packet STARTED :=20
>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=3Dtr2a
>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.j=
ava: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:22=
46)
>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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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:22=
46)
>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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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(DelegatingMethodAccessorI=
mpl.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(DelegatingMethodAccessorI=
mpl.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.ja=
va: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
> =20
>
>> -----Original Message-----
>>From: 	Marsh, Ralph =20
>>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 =20
>>	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.=20
>>
>>	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...>=20
>>	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=3D%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=3Dorg.tanukisoftware.wrapper.WrapperStartStopApp
>>
>>	# Java Classpath (include wrapper.jar)  Add class path elements as
>>	#  needed starting from 1
>>	wrapper.java.classpath.1=3D../common/lib/wrapper.jar
>>	wrapper.java.classpath.2=3D%java_home%/lib/tools.jar
>>	wrapper.java.classpath.3=3D../bin/bootstrap.jar
>>
>>	# Java Library Path (location of Wrapper.DLL or libwrapper.so)
>>	wrapper.java.library.path.1=3D../common/lib
>>
>>	# Java Additional Parameters
>>	wrapper.java.additional.1=3D-server
>>	wrapper.java.additional.2=3D-XX:+UseParNewGC
>>	wrapper.java.additional.3=3D-XX:MaxNewSize=3D24m
>>	wrapper.java.additional.4=3D-XX:NewSize=3D24m
>>	wrapper.java.additional.5=3D-XX:SurvivorRatio=3D128
>>	wrapper.java.additional.6=3D-XX:+UseConcMarkSweepGC
>>	wrapper.java.additional.7=3D-XX:MaxTenuringThreshold=3D0
>>	wrapper.java.additional.8=3D-XX:CMSInitiatingOccupancyFraction=3D60
>>	=
wrapper.java.additional.9=3D-Djava.endorsed.dirs=3D../bin;../common/endor=
sed
>>	wrapper.java.additional.10=3D-Dcatalina.base=3D..
>>	wrapper.java.additional.11=3D-Dcatalina.home=3D..
>>	wrapper.java.additional.12=3D-Djava.io.tmpdir=3D../temp
>>	                       =20
>>	#wrapper.java.additional.13=3D-verbosegc
>>	#wrapper.java.additional.14=3D-XX:+PrintGCTimeStamps
>>	#wrapper.java.additional.15=3D-XX:+PrintGCDetails
>>	#wrapper.java.additional.13=3D-XX:+PrintTenuringDistribution
>>
>>
>>	#wrapper.java.additional.7=3D-verbosegc
>>
>>	# Initial Java Heap Size (in MB)
>>	wrapper.java.initmemory=3D1200
>>
>>	# Maximum Java Heap Size (in MB)
>>	wrapper.java.maxmemory=3D1200
>>
>>	# 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=3Dorg.apache.catalina.startup.Bootstrap
>>	wrapper.app.parameter.2=3D1
>>	wrapper.app.parameter.3=3Dstart
>>
>>	# 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=3Dorg.apache.catalina.startup.Bootstrap
>>	wrapper.app.parameter.5=3Dtrue
>>	wrapper.app.parameter.6=3D1
>>	wrapper.app.parameter.7=3Dstop
>>
>>	#********************************************************************
>>	# Wrapper Logging Properties
>>	#********************************************************************
>>	# Format of output for the console.  (See docs for formats)
>>	wrapper.console.format=3DPM
>>
>>	# Log Level for console output.  (See docs for log levels)
>>	wrapper.console.loglevel=3DINFO
>>
>>	# Log file to use for wrapper output logging.
>>	wrapper.logfile=3D../logs/wrapper.log
>>
>>	# Format of output for the log file.  (See docs for formats)
>>	wrapper.logfile.format=3DLPTM
>>
>>	# Log Level for log file output.  (See docs for log levels)
>>	wrapper.logfile.loglevel=3DSTATUS
>>
>>	# 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 =3D 10 megabytes.
>>	wrapper.logfile.maxsize=3D500k
>>
>>	# 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=3D0
>>
>>	# Log Level for sys/event log output.  (See docs for log levels)
>>	wrapper.syslog.loglevel=3DNONE
>>
>>	#********************************************************************
>>	# 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=3Dtomcat-rights2a
>>
>>	# Display name of the service
>>	wrapper.ntservice.displayname=3Dtomcat-rights2a
>>
>>	# Description of the service
>>	wrapper.ntservice.description=3Dtomcat-rights2a
>>
>>	# Service dependencies.  Add dependencies as needed starting from 1
>>	wrapper.ntservice.dependency.1=3D
>>
>>	# Mode in which the service is installed.  AUTO_START or DEMAND_START
>>	wrapper.ntservice.starttype=3DAUTO_START
>>
>>	# Allow the service to interact with the desktop.
>>	wrapper.ntservice.interactive=3Dfalse
>>
>>   =20
>>




-------------------------------------------------------
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=3D6595&alloc_id=3D14396&op=3Dclick
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-us...
 
[truncated message content]

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

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

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
> 

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

[Leif M. <le...@ta...>]

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