From: Ramakrishna Bv S. <ram...@in...> - 2008-02-11 05:19:35
|
Hi Leif Mortenson, Thank you for quick response. Please check my answers in Blue for the questions. Please find the attachment for the log. (See attached file: wrapperLog.txt) I have checked the logs on other days as well , this issue is occuring but for the recovery time is less, please check the log below: INFO | jvm 9 | 2008/02/10 01:28:46 | Send a packet PING : ok DEBUG | wrapperp | 2008/02/10 01:28:46 | read a packet PING : ok DEBUG | wrapper | 2008/02/10 01:28:46 | Got ping response from JVM DEBUG | wrapperp | 2008/02/10 01:28:50 | send a packet PING : ping INFO | jvm 9 | 2008/02/10 01:28:50 | Received a packet PING : ping INFO | jvm 9 | 2008/02/10 01:28:50 | Send a packet PING : ok DEBUG | wrapperp | 2008/02/10 01:28:50 | read a packet PING : ok DEBUG | wrapper | 2008/02/10 01:28:50 | Got ping response from JVM DEBUG | wrapperp | 2008/02/10 01:28:54 | send a packet PING : ping DEBUG | wrapper | 2008/02/10 01:29:25 | ServiceControlHandler(4) DEBUG | wrapperp | 2008/02/10 01:29:25 | send a packet SERVICE_CONTROL_CODE : 4 DEBUG | wrapperp | 2008/02/10 01:29:25 | socket send failed. (10053) DEBUG | wrapper | 2008/02/10 01:29:25 | SERVICE_CONTROL_INTERROGATE INFO | jvm 9 | 2008/02/10 01:29:25 | Read Timed out. (Last Ping was 30300 milliseconds ago) INFO | jvm 9 | 2008/02/10 01:29:25 | Wrapper Manager: The Wrapper code did not ping the JVM for 30 seconds. Quit and let the Wrapper resynch. INFO | jvm 9 | 2008/02/10 01:29:25 | Send a packet RESTART : restart INFO | jvm 9 | 2008/02/10 01:29:25 | Thread, Wrapper-Connection, handling the shutdown process. INFO | jvm 9 | 2008/02/10 01:29:25 | calling listener.stop() INFO | jvm 9 | 2008/02/10 01:29:25 | Waiting for WrapperListener.stop runner thread to complete. INFO | jvm 9 | 2008/02/10 01:29:25 | WrapperListener.stop runner thread started. INFO | jvm 9 | 2008/02/10 01:29:25 | WrapperSimpleApp: stop(1) INFO | jvm 9 | 2008/02/10 01:29:25 | WrapperListener.stop runner thread stopped. INFO | jvm 9 | 2008/02/10 01:29:25 | returned from listener.stop() -> 1 INFO | jvm 9 | 2008/02/10 01:29:25 | shutdownJVM(1) Thread:Wrapper-Connection INFO | jvm 9 | 2008/02/10 01:29:25 | Send a packet STOPPED : 1 INFO | jvm 9 | 2008/02/10 01:29:25 | Closing socket. INFO | jvm 9 | 2008/02/10 01:29:25 | calling System.exit(1) INFO | jvm 9 | 2008/02/10 01:29:25 | 2008-02-10 01:29:23,188 |INFO|SequencerTool|shutting down INFO | jvm 9 | 2008/02/10 01:29:25 | 2008-02-10 01:29:23,266 |INFO|SequencerTool|ok. INFO | jvm 9 | 2008/02/10 01:29:25 | 2008-02-10 01:29:23,266 |INFO|SequencerTool|stopped. DEBUG | wrapperp | 2008/02/10 01:29:25 | server listening on port 32002. INFO | wrapper | 2008/02/10 01:29:25 | Wrapper Process has not received any CPU time for 30 seconds. Extending timeouts. DEBUG | wrapper | 2008/02/10 01:29:25 | JVM process exited with a code of 1, setting the wrapper exit code to 1. ERROR | wrapper | 2008/02/10 01:29:25 | JVM exited unexpectedly. DEBUG | wrapper | 2008/02/10 01:29:25 | ServiceControlHandler(4) DEBUG | wrapperp | 2008/02/10 01:29:25 | socket not open, so packet not sent SERVICE_CONTROL_CODE : 4 DEBUG | wrapper | 2008/02/10 01:29:25 | SERVICE_CONTROL_INTERROGATE DEBUG | wrapper | 2008/02/10 01:29:25 | Waiting 5 seconds before launching another JVM. DEBUG | wrapper | 2008/02/10 01:29:29 | Classpath element, wrapper.java.classpath.10, does not exist: ../classes STATUS | wrapper | 2008/02/10 01:29:29 | Launching a JVM... _________________________________________________________________________________________________ INFO | jvm 7 | 2008/02/06 02:31:49 | Received a packet SERVICE_CONTROL_CODE : 4 INFO | jvm 7 | 2008/02/06 02:31:49 | ServiceControlCode from Wrapper with code 4 DEBUG | wrapperp | 2008/02/06 02:31:49 | send a packet PING : ping INFO | jvm 7 | 2008/02/06 02:31:49 | Received a packet PING : ping INFO | jvm 7 | 2008/02/06 02:31:49 | Send a packet PING : ok DEBUG | wrapperp | 2008/02/06 02:31:50 | read a packet PING : ok DEBUG | wrapper | 2008/02/06 02:31:50 | Got ping response from JVM DEBUG | wrapperp | 2008/02/06 02:31:54 | send a packet PING : ping INFO | jvm 7 | 2008/02/06 02:31:54 | Received a packet PING : ping INFO | jvm 7 | 2008/02/06 02:31:54 | Send a packet PING : ok DEBUG | wrapperp | 2008/02/06 02:31:54 | read a packet PING : ok DEBUG | wrapper | 2008/02/06 02:31:54 | Got ping response from JVM DEBUG | wrapperp | 2008/02/06 02:31:58 | send a packet PING : ping DEBUG | wrapper | 2008/02/06 02:32:50 | ServiceControlHandler(4) DEBUG | wrapperp | 2008/02/06 02:32:50 | send a packet SERVICE_CONTROL_CODE : 4 DEBUG | wrapperp | 2008/02/06 02:32:50 | socket send failed. (10053) DEBUG | wrapper | 2008/02/06 02:32:50 | SERVICE_CONTROL_INTERROGATE DEBUG | wrapper | 2008/02/06 02:32:50 | ServiceControlHandler(4) DEBUG | wrapperp | 2008/02/06 02:32:50 | socket not open, so packet not sent SERVICE_CONTROL_CODE : 4 DEBUG | wrapper | 2008/02/06 02:32:50 | SERVICE_CONTROL_INTERROGATE INFO | jvm 7 | 2008/02/06 02:32:50 | Read Timed out. (Last Ping was 30400 milliseconds ago) INFO | jvm 7 | 2008/02/06 02:32:50 | Wrapper Manager: The Wrapper code did not ping the JVM for 30 seconds. Quit and let the Wrapper resynch. INFO | jvm 7 | 2008/02/06 02:32:50 | Send a packet RESTART : restart INFO | jvm 7 | 2008/02/06 02:32:50 | Thread, Wrapper-Connection, handling the shutdown process. INFO | jvm 7 | 2008/02/06 02:32:50 | calling listener.stop() INFO | jvm 7 | 2008/02/06 02:32:50 | Waiting for WrapperListener.stop runner thread to complete. INFO | jvm 7 | 2008/02/06 02:32:50 | WrapperListener.stop runner thread started. INFO | jvm 7 | 2008/02/06 02:32:50 | WrapperSimpleApp: stop(1) INFO | jvm 7 | 2008/02/06 02:32:50 | WrapperListener.stop runner thread stopped. INFO | jvm 7 | 2008/02/06 02:32:50 | returned from listener.stop() -> 1 INFO | jvm 7 | 2008/02/06 02:32:50 | shutdownJVM(1) Thread:Wrapper-Connection INFO | jvm 7 | 2008/02/06 02:32:50 | Send a packet STOPPED : 1 INFO | jvm 7 | 2008/02/06 02:32:50 | Closing socket. INFO | jvm 7 | 2008/02/06 02:32:50 | calling System.exit(1) INFO | jvm 7 | 2008/02/06 02:32:50 | 2008-02-06 02:32:26,750 |INFO|SequencerTool|shutting down DEBUG | wrapperp | 2008/02/06 02:32:50 | server listening on port 32002. INFO | wrapper | 2008/02/06 02:32:50 | Wrapper Process has not received any CPU time for 51 seconds. Extending timeouts. DEBUG | wrapper | 2008/02/06 02:32:50 | JVM process exited with a code of 1, setting the wrapper exit code to 1. ERROR | wrapper | 2008/02/06 02:32:50 | JVM exited unexpectedly. DEBUG | wrapper | 2008/02/06 02:32:50 | Waiting 5 seconds before launching another JVM. DEBUG | wrapper | 2008/02/06 02:32:54 | Classpath element, wrapper.java.classpath.10, does not exist: ../classes STATUS | wrapper | 2008/02/06 02:32:54 | Launching a JVM... Best Regards, Ram IBM Global Services India Pvt. Ltd. Mindspace, Survey No 64, APIIC Software Layout, Hi-tech City, Hyderabad -500 081 INDIA Phone: +91-40-66956756 Leif Mortenson <leif@tanukisoftw are.com> To Sent by: wra...@li... wrapper-user-boun cc ce...@li...urcef orge.net Subject Re: [Wrapper-user] Issue with wrapper 02/08/2008 01:17 PM Please respond to wrapper-user@list s.sourceforge.net Ramakrishna, According to the log, the backend socket between the Wrapper and Java process was somehow closed. The Wrapper is failing saying that it can no longer communicate with the JVM. It keeps going though because the JVM process is still running. The JVM then gives up after around 30 seconds because it has not received any communications from the Wrapper for that long. This is a safety feature to shut the JVM process down just in case the Wrapper process should ever crash. Once the Wrapper detects that the JVM is shutdown, it is correctly restarting the JVM. The question is why is the backend socket being closed? This is not a problem I have ever seen or heard of in the past. Is anything else in the log file earlier than what you sent? How easy is this to reproduce? A: We cannot reproduce. Does it always happen at the same time? A: No,it does not happen at the sametime. Is it possible that some other application on your system is closing the socket? A:Can't say whether someother application on the system might be trying to close the socket.Another two applications are running on the same machine with wrapper having same configuration. Is your system under load at the time of this reset? A: Yes, it was under load. Does your Java application respond during the 30 seconds between the socket being closed and the JVM shutting itself down? A: Can't answer Cheers, Leif Ramakrishna Bv Sanku wrote: > > Hi All, > > I came across a issue with wrapper, the Wrapper is getting degraded > for sometime and getting into normal state after some time. Please > check the wrapper log below. > > Can anyone help me and provide a solution, how can this be rectified. > > *Information from the wrapper log* > WrapperManager class initialized by thread: main Using classloader: > sun.misc.Launcher$AppClassLoader@27e3570f > ............... > Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org > ............... > > Extract from wrapper log > > DEBUG | wrapper | 2008/02/08 01:40:42 | ServiceControlHandler(4) > DEBUG | wrapperp | 2008/02/08 01:40:42 | send a packet > SERVICE_CONTROL_CODE : 4 > DEBUG | wrapperp | 2008/02/08 01:40:42 | socket send failed. (10053) > DEBUG | wrapper | 2008/02/08 01:40:42 | SERVICE_CONTROL_INTERROGATE > DEBUG | wrapper | 2008/02/08 01:40:42 | ServiceControlHandler(4) > DEBUG | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet > not sent SERVICE_CONTROL_CODE : 4 > DEBUG | wrapper | 2008/02/08 01:40:42 | SERVICE_CONTROL_INTERROGATE > INFO | jvm 8 | 2008/02/08 01:40:42 | Read Timed out. (Last Ping > was 30600 milliseconds ago) > INFO | jvm 8 | 2008/02/08 01:40:42 | Wrapper Manager: The Wrapper > code did not ping the JVM for 30 seconds. Quit and let the Wrapper > resynch. > INFO | jvm 8 | 2008/02/08 01:40:42 | Send a packet RESTART : restart > INFO | jvm 8 | 2008/02/08 01:40:42 | Thread, Wrapper-Connection, > handling the shutdown process. > INFO | jvm 8 | 2008/02/08 01:40:42 | calling listener.stop() > INFO | jvm 8 | 2008/02/08 01:40:42 | Waiting for > WrapperListener.stop runner thread to complete. > INFO | jvm 8 | 2008/02/08 01:40:42 | WrapperListener.stop runner > thread started. > INFO | jvm 8 | 2008/02/08 01:40:42 | WrapperSimpleApp: stop(1) > INFO | jvm 8 | 2008/02/08 01:40:42 | WrapperListener.stop runner > thread stopped. > INFO | jvm 8 | 2008/02/08 01:40:42 | returned from > listener.stop() -> 1 > INFO | jvm 8 | 2008/02/08 01:40:42 | shutdownJVM(1) > Thread:Wrapper-Connection > INFO | jvm 8 | 2008/02/08 01:40:42 | Send a packet STOPPED : 1 > INFO | jvm 8 | 2008/02/08 01:40:42 | Closing socket. > INFO | jvm 8 | 2008/02/08 01:40:42 | calling System.exit(1) > INFO | jvm 8 | 2008/02/08 01:40:42 | 2008-02-08 > 01:40:22,031|INFO|SequencerTool|shutting down > DEBUG | wrapperp | 2008/02/08 01:40:42 | server listening on port 32002. > DEBUG | wrapper | 2008/02/08 01:40:42 | ServiceControlHandler(4) > DEBUG | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet > not sent SERVICE_CONTROL_CODE : 4 > DEBUG | wrapper | 2008/02/08 01:40:42 | SERVICE_CONTROL_INTERROGATE > INFO | wrapper | 2008/02/08 01:40:42 | Wrapper Process has not > received any CPU time for 48 seconds. Extending timeouts. > DEBUG | wrapper | 2008/02/08 01:40:42 | JVM process exited with a > code of 1, setting the wrapper exit code to 1. > ERROR | wrapper | 2008/02/08 01:40:42 | JVM exited unexpectedly. > DEBUG | wrapper | 2008/02/08 01:40:42 | Waiting 5 seconds before > launching another JVM. > DEBUG | wrapper | 2008/02/08 01:40:46 | Classpath element, > wrapper.java.classpath.10, does not exist: ../classes > STATUS | wrapper | 2008/02/08 01:40:46 | Launching a JVM... > NONE | wrapper | 2008/02/08 01:40:46 | command: > "D:\IBM\WBIServer\jre\bin\java.exe" > -Dsequencer.context=AU04QWS130DCA32 > -Dsequencer.logs=d:\wppaup\runtime\var\sequencer\logs > -Drepository.directory=D:\IBM\Sequencer -Djava.library.path="./lib" > -classpath > "./lib/wrapper.jar;./lib/commons-collections-3.1.jar;./lib/commons-lang-2.1.jar;./lib/commons-logging-1.0.4.jar;./lib/commons-net-1.4.1.jar;./lib/jakarta-oro.jar;./lib/log4j-1.2.7.jar;./lib/spring.jar;./lib/velocity-1.4.jar;../classes;./lib/sequencer.jar" > -Dwrapper.key="2ZXzPWYAZ6Ry7obW" -Dwrapper.port=32002 > -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 > -Dwrapper.debug="TRUE" -Dwrapper.pid=2508 -Dwrapper.version="3.2.3" > -Dwrapper.native_library="wrapper" -Dwrapper.service="TRUE" > -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=9 > org.tanukisoftware.wrapper.WrapperSimpleApp SequencerTool LOOP > DEBUG | wrapper | 2008/02/08 01:40:46 | JVM started (PID=9500) ------------------------------------------------------------------------- This SF.net email is sponsored by: Microsoft Defy all challenges. Microsoft(R) Visual Studio 2008. http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/ _______________________________________________ Wrapper-user mailing list Wra...@li... https://lists.sourceforge.net/lists/listinfo/wrapper-user |