RE: [Wrapper-user] Tomcat 5.5.9/JRockit won't shutdown cleanly

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

Leif,

Here is the full log dump using debug mode:

STATUS | wrapper  | 2005/08/22 09:47:59 | --> Wrapper Started as Console
DEBUG  | wrapper  | 2005/08/22 09:47:59 | Using system timer.
DEBUG  | wrapperp | 2005/08/22 09:47:59 | server listening on port 32000.
STATUS | wrapper  | 2005/08/22 09:47:59 | Launching a JVM...
DEBUG  | wrapper  | 2005/08/22 09:47:59 | command:
"c:\jrockit-jdk1.5.0_03\bin\java" -Dmysql.home=c:/MySQL4.1/bin
-Djava.endorsed.dirs=../common/endorsed -Dcatalina.base=..
-Dcatalina.home=.. -Djava.io.tmpdir=../temp -Xms16m -Xmx284m
-Djava.library.path="../common/lib" -classpath
"../common/lib/wrapper.jar;c:/jrockit-jdk1.5.0_03/lib/tools.jar;../bin/boots
trap.jar" -Dwrapper.key="AAHaDdbyBwC53EIC" -Dwrapper.port=32000
-Dwrapper.debug="TRUE" -Dwrapper.use_system_time="TRUE"
-Dwrapper.version="3.1.2" -Dwrapper.native_library="wrapper"
-Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=1
org.tanukisoftware.wrapper.WrapperStartStopApp
org.apache.catalina.startup.Bootstrap 1 start
org.apache.catalina.startup.Bootstrap true 1 stop
DEBUG  | wrapper  | 2005/08/22 09:47:59 | JVM started (PID=3976)
INFO   | jvm 1    | 2005/08/22 09:48:00 | WrapperManager class initialized
by thread: Main Thread  Using classloader:
sun.misc.Launcher$AppClassLoader@127439
INFO   | jvm 1    | 2005/08/22 09:48:00 | Wrapper Manager: JVM #1
INFO   | jvm 1    | 2005/08/22 09:48:00 | Wrapper Manager: Registering
shutdown hook
INFO   | jvm 1    | 2005/08/22 09:48:00 | Wrapper Manager: Using wrapper
INFO   | jvm 1    | 2005/08/22 09:48:00 | Loaded native library: wrapper.dll
INFO   | jvm 1    | 2005/08/22 09:48:00 | Calling native initialization
method.
INFO   | jvm 1    | 2005/08/22 09:48:00 | Initializing WrapperManager native
library.
INFO   | jvm 1    | 2005/08/22 09:48:00 | Java Executable:
c:\jrockit-jdk1.5.0_03\bin\java.exe
INFO   | jvm 1    | 2005/08/22 09:48:00 | Windows version: 5.1.2600
INFO   | jvm 1    | 2005/08/22 09:48:00 | Java Version   : 1.5.0_03-b07 BEA
JRockit(R)
INFO   | jvm 1    | 2005/08/22 09:48:00 | Java VM Vendor : BEA Systems, Inc.
INFO   | jvm 1    | 2005/08/22 09:48:00 | 
INFO   | jvm 1    | 2005/08/22 09:48:00 | Wrapper (Version 3.1.2)
http://wrapper.tanukisoftware.org
INFO   | jvm 1    | 2005/08/22 09:48:00 | 
INFO   | jvm 1    | 2005/08/22 09:48:00 |
WrapperManager.start(org.tanukisoftware.wrapper.WrapperStartStopApp@131868,
args["start"]) called by thread: Main Thread
INFO   | jvm 1    | 2005/08/22 09:48:00 | Open socket to wrapper...
INFO   | jvm 1    | 2005/08/22 09:48:00 | Opened Socket
INFO   | jvm 1    | 2005/08/22 09:48:00 | Send a packet KEY :
AAHaDdbyBwC53EIC
INFO   | jvm 1    | 2005/08/22 09:48:00 |
handleSocket(Socket[addr=localhost/127.0.0.1,port=32000,localport=1309])
DEBUG  | wrapperp | 2005/08/22 09:48:00 | accepted a socket from 127.0.0.1
on port 1309
DEBUG  | wrapperp | 2005/08/22 09:48:00 | read a packet KEY :
AAHaDdbyBwC53EIC
DEBUG  | wrapper  | 2005/08/22 09:48:00 | Got key from JVM: AAHaDdbyBwC53EIC
DEBUG  | wrapperp | 2005/08/22 09:48:00 | send a packet LOW_LOG_LEVEL : 1
DEBUG  | wrapperp | 2005/08/22 09:48:00 | send a packet PING_TIMEOUT : 30
DEBUG  | wrapper  | 2005/08/22 09:48:00 | Start Application.
DEBUG  | wrapperp | 2005/08/22 09:48:00 | send a packet START : start
INFO   | jvm 1    | 2005/08/22 09:48:01 | Received a packet LOW_LOG_LEVEL :
1
INFO   | jvm 1    | 2005/08/22 09:48:01 | Wrapper Manager: LowLogLevel from
Wrapper is 1
INFO   | jvm 1    | 2005/08/22 09:48:01 | Received a packet PING_TIMEOUT :
30
INFO   | jvm 1    | 2005/08/22 09:48:01 | Wrapper Manager: PingTimeout from
Wrapper is 30000
INFO   | jvm 1    | 2005/08/22 09:48:01 | Received a packet START : start
INFO   | jvm 1    | 2005/08/22 09:48:01 | calling listener.start()
INFO   | jvm 1    | 2005/08/22 09:48:01 | WrapperStartStopApp: start(args)
INFO   | jvm 1    | 2005/08/22 09:48:01 | WrapperStartStopApp: invoking
start main method
INFO   | jvm 1    | 2005/08/22 09:48:02 | Aug 22, 2005 9:48:02 AM
org.apache.coyote.http11.Http11Protocol init
INFO   | jvm 1    | 2005/08/22 09:48:02 | INFO: Initializing Coyote HTTP/1.1
on http-8080
INFO   | jvm 1    | 2005/08/22 09:48:02 | Aug 22, 2005 9:48:02 AM
org.apache.catalina.startup.Catalina load
INFO   | jvm 1    | 2005/08/22 09:48:02 | INFO: Initialization processed in
1151 ms
INFO   | jvm 1    | 2005/08/22 09:48:02 | Aug 22, 2005 9:48:02 AM
org.apache.catalina.core.StandardService start
INFO   | jvm 1    | 2005/08/22 09:48:02 | INFO: Starting service Catalina
INFO   | jvm 1    | 2005/08/22 09:48:02 | Aug 22, 2005 9:48:02 AM
org.apache.catalina.core.StandardEngine start
INFO   | jvm 1    | 2005/08/22 09:48:02 | INFO: Starting Servlet Engine:
Apache Tomcat/5.5.9
INFO   | jvm 1    | 2005/08/22 09:48:02 | Aug 22, 2005 9:48:02 AM
org.apache.catalina.core.StandardHost start
INFO   | jvm 1    | 2005/08/22 09:48:02 | INFO: XML validation disabled
INFO   | jvm 1    | 2005/08/22 09:48:02 | WrapperStartStopApp: start(args)
end.  Main Completed=false, exitCode=null
INFO   | jvm 1    | 2005/08/22 09:48:02 | returned from listener.start()
INFO   | jvm 1    | 2005/08/22 09:48:02 | Send a packet STARTED : 
DEBUG  | wrapperp | 2005/08/22 09:48:02 | read a packet STARTED : 
DEBUG  | wrapper  | 2005/08/22 09:48:02 | JVM signalled that it was started.
DEBUG  | wrapperp | 2005/08/22 09:48:03 | send a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:03 | Received a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:03 | Send a packet PING : ok
DEBUG  | wrapperp | 2005/08/22 09:48:03 | read a packet PING : ok
DEBUG  | wrapper  | 2005/08/22 09:48:03 | Got ping response from JVM
INFO   | jvm 1    | 2005/08/22 09:48:04 | Aug 22, 2005 9:48:04 AM
org.apache.coyote.http11.Http11Protocol start
INFO   | jvm 1    | 2005/08/22 09:48:04 | INFO: Starting Coyote HTTP/1.1 on
http-8080
INFO   | jvm 1    | 2005/08/22 09:48:04 | Aug 22, 2005 9:48:04 AM
org.apache.jk.common.ChannelSocket init
INFO   | jvm 1    | 2005/08/22 09:48:04 | INFO: JK: ajp13 listening on
/0.0.0.0:8009
INFO   | jvm 1    | 2005/08/22 09:48:04 | Aug 22, 2005 9:48:04 AM
org.apache.jk.server.JkMain start
INFO   | jvm 1    | 2005/08/22 09:48:04 | INFO: Jk running ID=0 time=0/100
config=null
INFO   | jvm 1    | 2005/08/22 09:48:04 | Aug 22, 2005 9:48:04 AM
org.apache.catalina.storeconfig.StoreLoader load
INFO   | jvm 1    | 2005/08/22 09:48:04 | INFO: Find registry
server-registry.xml at classpath resource
INFO   | jvm 1    | 2005/08/22 09:48:04 | Aug 22, 2005 9:48:04 AM
org.apache.catalina.startup.Catalina start
INFO   | jvm 1    | 2005/08/22 09:48:04 | INFO: Server startup in 2113 ms
DEBUG  | wrapperp | 2005/08/22 09:48:07 | send a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:07 | Received a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:07 | Send a packet PING : ok
DEBUG  | wrapperp | 2005/08/22 09:48:07 | read a packet PING : ok
DEBUG  | wrapper  | 2005/08/22 09:48:07 | Got ping response from JVM
DEBUG  | wrapperp | 2005/08/22 09:48:11 | send a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:11 | Received a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:11 | Send a packet PING : ok
DEBUG  | wrapperp | 2005/08/22 09:48:11 | read a packet PING : ok
DEBUG  | wrapper  | 2005/08/22 09:48:11 | Got ping response from JVM
DEBUG  | wrapperp | 2005/08/22 09:48:15 | send a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:15 | Received a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:15 | Send a packet PING : ok
DEBUG  | wrapperp | 2005/08/22 09:48:15 | read a packet PING : ok
DEBUG  | wrapper  | 2005/08/22 09:48:15 | Got ping response from JVM
DEBUG  | wrapperp | 2005/08/22 09:48:19 | send a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:19 | Received a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:19 | Send a packet PING : ok
DEBUG  | wrapperp | 2005/08/22 09:48:19 | read a packet PING : ok
DEBUG  | wrapper  | 2005/08/22 09:48:19 | Got ping response from JVM
DEBUG  | wrapperp | 2005/08/22 09:48:23 | send a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:23 | Received a packet PING : ping
INFO   | jvm 1    | 2005/08/22 09:48:23 | Send a packet PING : ok
DEBUG  | wrapperp | 2005/08/22 09:48:23 | read a packet PING : ok
DEBUG  | wrapper  | 2005/08/22 09:48:23 | Got ping response from JVM
STATUS | wrapper  | 2005/08/22 09:48:24 | CTRL-C trapped.  Shutting down.
DEBUG  | wrapper  | 2005/08/22 09:48:24 | wrapperStopProcess(0) called.
INFO   | jvm 1    | 2005/08/22 09:48:24 | Got Control Signal 0->200
INFO   | jvm 1    | 2005/08/22 09:48:24 | Handled signal
INFO   | jvm 1    | 2005/08/22 09:48:24 | Processing control
event(WRAPPER_CTRL_C_EVENT)
INFO   | jvm 1    | 2005/08/22 09:48:24 | WrapperStartStopApp:
controlEvent(200) Stopping
INFO   | jvm 1    | 2005/08/22 09:48:24 | WrapperManager.stop(0) called by
thread: Wrapper-Control-Event-Monitor
INFO   | jvm 1    | 2005/08/22 09:48:24 | Send a packet STOP : 0
DEBUG  | wrapperp | 2005/08/22 09:48:24 | read a packet STOP : 0
DEBUG  | wrapper  | 2005/08/22 09:48:24 | JVM requested a shutdown. (0)
DEBUG  | wrapper  | 2005/08/22 09:48:24 | wrapperStopProcess(0) called.
(IGNORED)
DEBUG  | wrapper  | 2005/08/22 09:48:24 | Sending stop signal to JVM
DEBUG  | wrapperp | 2005/08/22 09:48:24 | send a packet STOP : NULL
INFO   | jvm 1    | 2005/08/22 09:48:24 | Received a packet STOP : 
INFO   | jvm 1    | 2005/08/22 09:48:25 | Thread,
Wrapper-Control-Event-Monitor, handling the shutdown process.
INFO   | jvm 1    | 2005/08/22 09:48:25 | calling listener.stop()
INFO   | jvm 1    | 2005/08/22 09:48:25 | WrapperStartStopApp: stop(0)
INFO   | jvm 1    | 2005/08/22 09:48:25 | WrapperStartStopApp: invoking stop
main method
INFO   | jvm 1    | 2005/08/22 09:48:25 | Aug 22, 2005 9:48:25 AM
org.apache.coyote.http11.Http11Protocol pause
INFO   | jvm 1    | 2005/08/22 09:48:25 | INFO: Pausing Coyote HTTP/1.1 on
http-8080
INFO   | jvm 1    | 2005/08/22 09:48:25 | WrapperStartStopApp: stop main
method completed
INFO   | jvm 1    | 2005/08/22 09:48:25 | WrapperStartStopApp: stopping.
Waiting for 8 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:26 | WrapperStartStopApp: stopping.
Waiting for 8 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:26 | Aug 22, 2005 9:48:26 AM
org.apache.catalina.core.StandardService stop
INFO   | jvm 1    | 2005/08/22 09:48:26 | INFO: Stopping service Catalina
INFO   | jvm 1    | 2005/08/22 09:48:27 | Aug 22, 2005 9:48:26 AM
org.apache.coyote.http11.Http11Protocol destroy
INFO   | jvm 1    | 2005/08/22 09:48:27 | INFO: Stopping Coyote HTTP/1.1 on
http-8080
INFO   | jvm 1    | 2005/08/22 09:48:27 | WrapperStartStopApp: start main
method completed
INFO   | jvm 1    | 2005/08/22 09:48:27 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:28 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:29 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:30 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:31 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:32 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:33 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:34 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:35 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:36 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:37 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:38 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:39 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:40 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:41 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:42 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:43 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:44 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:45 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:46 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:47 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:48 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:49 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:50 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:51 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:52 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:53 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:54 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:55 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:56 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:57 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
INFO   | jvm 1    | 2005/08/22 09:48:58 | WrapperStartStopApp: stopping.
Waiting for 6 threads to complete.
ERROR  | wrapper  | 2005/08/22 09:48:58 | Shutdown failed: Timed out waiting
for signal from JVM.
ERROR  | wrapper  | 2005/08/22 09:48:58 | JVM did not exit on request,
terminated
STATUS | wrapper  | 2005/08/22 09:48:59 | <-- Wrapper Stopped

-----Original Message-----
From: wra...@li...
[mailto:wra...@li...] On Behalf Of Leif
Mortenson
Sent: Sunday, August 21, 2005 8:07 AM
To: wra...@li...
Subject: Re: [Wrapper-user] Tomcat 5.5.9/JRockit won't shutdown cleanly

Brad,
I have never used JRocket myself. But other users have in the past. 
Could you run
another test with wrapper.debug=true set and then post the results.

Cheers,
Leif

Brad Baynes wrote:

> Hi,
>
> Running Tomcat 5.5.9 either as a service or via the console with 
> JRockit (using the latest: JDK 5.0 Update 3 (RR25.2.0-28)) as the jvm 
> starts up ok but does not shutdown cleanly. It shuts down fine if I 
> use the sun jvm.
>
> The following logs are produced at the end of the process:
>
> INFO | jvm 1 | 2005/08/18 14:53:30 | WrapperStartStopApp: stopping. 
> Waiting for 6 threads to complete.
>
> ERROR | wrapper | 2005/08/18 14:53:30 | Shutdown failed: Timed out 
> waiting for signal from JVM.
>
> ERROR | wrapper | 2005/08/18 14:53:30 | JVM did not exit on request, 
> terminated
>
> STATUS | wrapper | 2005/08/18 14:53:31 | <-- Wrapper Stopped
>
> This is a clean 5.5.9 install as I don't even have my webapp in there yet.
>
> Thanks for any help.
>

-------------------------------------------------------
SF.Net email is Sponsored by the Better Software Conference & EXPO
September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices
Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA
Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf
_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user