Re: [Wrapper-user] SERVICE_CONTROL_INTERROGATE - last message before wrapper dies

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

Krishna,
    2.2.9.  You are a long time user.   I have not seen this particular=20
problem show itself.  But
looking at the log you sent, I might have an idea as to the cause.

    First I want to verify that the log you sent is accurate as I am=20
basing my guess of it.  Notice
that the "DEBUG   | " is missing from the beginning of the log entry=20
that the
ServiceControlHandler was called.

    Up until version 3.1.0, the Wrapper was pretty much a single=20
threaded application.  In
3.1.0, I added a background timer thread and in the process uncovered a=20
couple
synchronization bugs in the logging code.   In earlier versions these=20
could be encountered
if a system signal was thrown (CTRL-C for example) or if the Service=20
Manager logged
an event as you are seeing.

    I had never seen this lead to a crash in earlier versions, but I was =

able to get frequent
crashes while developing 3.1.0.   They were fixed before that release.

    The problem is that two threads are attempting to log at the same=20
instant and are running
into problems while writing to the same buffer.  My guess is that this=20
might be leading to
a crash in your case.  This would be more likely on a multi-CPU system.

    How often does this happen on this machine?  Does it happen without=20
debug
logging enabled?  If so then my guess about a logging issue might not app=
ly.

    Are you able to locate any instances of the=20
"ServiceControlHandler(4)" log entry
in the log files where it does not crash?  I am wondering if it happens=20
every time,
or at what frequency?

    Would it be possible for you to try upgrading to 3.1.1 for this=20
customer?  The
wrapper.conf file should work pretty much as is.  The exceptions are=20
that you will
need to comment out the wrapper.pidfile and wrapper.port properties.
    The wrapper package names changed to org.tanukisoftware.wrapper  but =
the
old naming is still supported.

    Note that I am about to get 3.1.2 out the door.  This fixes a bug=20
which will
cause some JVMs to restart in late October.  You can wait for 3.1.2 or wo=
rk
around the problem in 3.1.1 by setting the following property.
    wrapper.use_system_time=3Dfalse

    I also just went through and added try catch blocks around all of=20
the entry
points on the Windows version.   If problems like persist in 3.1.2 then=20
it will
provide much more information as to where exactly the problem arose.

Cheers,
Leif

Krishna Kottamasu wrote:

> Our company has been using Wrapper to run our java application as a=20
> Windows service for several customers and it has been working great. =20
> At one of our customer sites however, the windows service for our=20
> application (that uses wrapper) seems to get terminated randomly.  The =

> OS is Windows 2000 Terminal.  There are no error messages in the=20
> wrapper's log file or our application's log file.  This is what it=20
> says in the Windows event log:
>
> *The service terminated unexpectedly.  It has done this 1 time(s). =20
> The following corrective action will be taken in 0 milliseconds: Run=20
> the configured recovery program.
> *
>
> The last lines I've always seen in the wrapper's log at the time the=20
> service goes down are:
>
> ServiceControlHandler(4)
> SERVICE_CONTROL_INTERROGATE
>
> It makes me wonder if the service some how is going down when those=20
> operations are being performed.
>
> I'm kind of at a loss here and I'm not sure how to debug this.  Our=20
> application runs just fine indefinitely when started from the command=20
> line with the same JVM arguments.
>
> I'm attaching my config. file and the output from the wrapper's log=20
> file along with this email.  Any suggestions or ideas in helping me=20
> debug this will be greatly appreciated.
>
> *Here's the relevant portion from the wrapper's log file.  (The=20
> service in this instance went down at 2004-08-30 08:01:58 AM)*
>
> INFO   | jvm 1    | 2004/08/30 08:01:58 | Received a packet 103 : ping
>
> INFO   | jvm 1    | 2004/08/30 08:01:58 | Send a packet 103 : ok
>
> DEBUG  | wrapperp | 2004/08/30 08:01:58 | read a packet 103 : ok
>
> wrapper  | 2004/08/30 08:01:58 | ServiceControlHandler(4)
>
> DEBUG  | wrapper  | 2004/08/30 08:01:58 |   SERVICE_CONTROL_INTERROGATE=

>
> STATUS | wrapper  | 2004/08/31 07:30:11 | --> Wrapper Started as Servic=
e
>
> DEBUG  | wrapperp | 2004/08/31 07:30:12 | server listening on port 1778=
=2E
>
> STATUS | wrapper  | 2004/08/31 07:30:13 | Launching a JVM...
>
> DEBUG  | wrapper  | 2004/08/31 07:30:13 | command:=20
> "C:\jdk1.3.1_09\bin\java.exe"=20
> -Dconfiguration_file=3DD:\Workforce\Prod\4.1.1/config_scheduler.xml=20
> -Dsun.rmi.dgc.server.gcInterval=3D0x7fffffffffffffff=20
> -Dsun.rmi.dgc.client.gcInterval=3D3600000 -Xms256m -Xmx800M=20
> -XX:MaxNewSize=3D500m -XX:NewRatio=3D3 -XX:SurvivorRatio=3D3=20
> -XX:+PrintTenuringDistribution=20
> -Djava.rmi.server.codebase=3Dfile:/classes -Xms25m -Xmx100m=20
> -Djava.library.path=3D"D:\Workforce\Prod\4.1.1\workforce\libs\wrapper" =

> -classpath=20
> "C:\jdk1.3.1_09\lib\tools.jar;classes;D:\Workforce\Prod\4.1.1;workforce=
\libs\OracleJDBC\9.0.1\classes12.zip;workforce\libs\sprinta\Sprinta2000.j=
ar;workforce\libs\db2jdbc\db2jcc.jar;workforce\libs\pat\patbinfree153.jar=
;workforce\libs\pat\patbin14_122.jar;workforce\libs\PVApps\pvBeans;workfo=
rce\libs\javamail\mail.jar;workforce\libs\jaf\activation.jar;workforce\li=
bs\log4j\log4j-apache.jar;workforce\libs\log4j\log4j-full.jar;workforce\l=
ibs\log4j\log4j.jar;workforce\libs\xml4j\xerces.jar;workforce\libs\old_wo=
rkforce;workforce\libs\rhino\js.jar;workforce\libs\jakarta-tomcat\lib\jas=
per.jar;workforce\libs\jakarta-tomcat\lib\servlet.jar;workforce\libs\jaka=
rta-tomcat\lib\webserver.jar;workforce\libs\jakarta-struts\lib\jdbc2_0-st=
dext.jar;workforce\libs\jakarta-struts\lib\struts.jar;workforce\libs\antl=
r\antlr.jar;workforce\libs\jce\jce1_2-do.jar;workforce\libs\jsse\jsse.jar=
;workforce\libs\jsse\jnet.jar;workforce\libs\jsse\jcert.jar;workforce\lib=
s\velocity\velocity-dvsl-0.45.jar;workforce\libs\velocity\velocity.jar;wo=
rkforce\libs\velocity\lib\logkit-1.0.jar;workforce\libs\velocity\lib\oro.=
jar;workforce\libs\velocity\lib\commons-collections.jar;workforce\libs\ht=
tpunit\lib\httpunit.jar;workforce\libs\httpunit\lib\Tidy.jar;workforce\li=
bs\xalan-j\xalan.jar;workforce\libs\xalan-j\xml-apis.jar;workforce\libs\x=
alan-j\xercesImpl.jar;workforce\libs\Actuate\ACJDesigner.jar;workforce\li=
bs\Actuate\ACJMain.jar;workforce\libs\Actuate\ACJRuntime.jar;workforce\li=
bs\Actuate\erdj9xl.jar;workforce\libs\Actuate\PDFExt.jar;workforce\libs\A=
ctuate\ReportDesignerHelp.jar;workforce\libs\xfunction\xFunction.jar;work=
force\libs\wrapper\wrapper.jar;workforce\libs\quartz1.0.3b3\commons-colle=
ctions.jar;workforce\libs\quartz1.0.3b3\commons-dbcp.jar;workforce\libs\q=
uartz1.0.3b3\commons-logging.jar;workforce\libs\quartz1.0.3b3\commons-poo=
l.jar;workforce\libs\quartz1.0.3b3\quartz.jar;workforce\libs\dom4j\dom4j-=
full.jar;workforce\libs\fop\fop.jar"=20
> -Dwrapper.key=3D"YAh6yPmC9cKwaq2z" -Dwrapper.port=3D1778=20
> -Dwrapper.debug=3D"TRUE" -Dwrapper.service=3D"TRUE"=20
> -Dwrapper.cpu.timeout=3D"10" -Dwrapper.jvmid=3D1=20
> com.silveregg.wrapper.WrapperSimpleApp=20
> com.workforcesoftware.scheduler.SchedulerService
>
> INFO   | wrapper  | 2004/08/31 07:30:13 | current directory:=20
> D:\Workforce\Prod\4.1.1\
>
> DEBUG  | wrapper  | 2004/08/31 07:30:13 | Java Virtual Machine started =

> (PID=3D588)
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Wrapper Manager: JVM #1
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Wrapper Manager: Registering =

> shutdown hook
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Wrapper Manager: Using wrappe=
r
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Calling native=20
> initialization method.
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Initializing WrapperManager=20
> native library.
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Java Executable:=20
> C:\jdk1.3.1_09\bin\java.exe
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Java Version   :=20
> 1.3.1_09-b03 Java HotSpot(TM) Client VM
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Java VM Vendor : Sun=20
> Microsystems Inc.
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 |
>
> INFO   | jvm 1    | 2004/08/31 07:30:13 | Wrapper (Version 2.2.9)
>
> *Wrapper's config file*
> # wrapper -i C:\work\rnd\research\wrapper\conf\wrapper_threads.conf
> #********************************************************************
> # Wrapper parameters
> #********************************************************************
> # Java Application
> wrapper.java.command=3DC:\jdk1.3.1_09\bin\java.exe
>
> wrapper.debug=3Dtrue
>
> # Java Main class
> wrapper.java.mainclass=3Dcom.silveregg.wrapper.WrapperSimpleApp
>
> # Java Classpath (include wrapper.jar)  Add class path elements as
> #  needed starting from 1
>
> wrapper.java.classpath.1=3DC:\jdk1.3.1_09\lib\tools.jar
> wrapper.java.classpath.2=3Dclasses
> wrapper.java.classpath.3=3DD:\Workforce\Prod\4.1.1
> wrapper.java.classpath.4=3Dworkforce\libs\OracleJDBC\9.0.1\classes12.zi=
p
> wrapper.java.classpath.5=3Dworkforce\libs\sprinta\Sprinta2000.jar
> wrapper.java.classpath.6=3Dworkforce\libs\db2jdbc\db2jcc.jar
> wrapper.java.classpath.7=3Dworkforce\libs\pat\patbinfree153.jar
> wrapper.java.classpath.8=3Dworkforce\libs\pat\patbin14_122.jar
> wrapper.java.classpath.9=3Dworkforce\libs\PVApps\pvBeans
> wrapper.java.classpath.10=3Dworkforce\libs\javamail\mail.jar
> wrapper.java.classpath.11=3Dworkforce\libs\jaf\activation.jar
> wrapper.java.classpath.12=3Dworkforce\libs\log4j\log4j-apache.jar
> wrapper.java.classpath.13=3Dworkforce\libs\log4j\log4j-full.jar
> wrapper.java.classpath.14=3Dworkforce\libs\log4j\log4j.jar
> wrapper.java.classpath.15=3Dworkforce\libs\xml4j\xerces.jar
> wrapper.java.classpath.16=3Dworkforce\libs\old_workforce
> wrapper.java.classpath.17=3Dworkforce\libs\rhino\js.jar
> wrapper.java.classpath.18=3Dworkforce\libs\jakarta-tomcat\lib\jasper.ja=
r
> wrapper.java.classpath.19=3Dworkforce\libs\jakarta-tomcat\lib\servlet.j=
ar
> wrapper.java.classpath.20=3Dworkforce\libs\jakarta-tomcat\lib\webserver=
=2Ejar
> wrapper.java.classpath.21=3Dworkforce\libs\jakarta-struts\lib\jdbc2_0-s=
tdext.jar=20
>
> wrapper.java.classpath.22=3Dworkforce\libs\jakarta-struts\lib\struts.ja=
r
> wrapper.java.classpath.23=3Dworkforce\libs\antlr\antlr.jar
> wrapper.java.classpath.24=3Dworkforce\libs\jce\jce1_2-do.jar
> wrapper.java.classpath.25=3Dworkforce\libs\jsse\jsse.jar
> wrapper.java.classpath.26=3Dworkforce\libs\jsse\jnet.jar
> wrapper.java.classpath.27=3Dworkforce\libs\jsse\jcert.jar
> wrapper.java.classpath.28=3Dworkforce\libs\velocity\velocity-dvsl-0.45.=
jar
> wrapper.java.classpath.29=3Dworkforce\libs\velocity\velocity.jar
> wrapper.java.classpath.30=3Dworkforce\libs\velocity\lib\logkit-1.0.jar
> wrapper.java.classpath.31=3Dworkforce\libs\velocity\lib\oro.jar
> wrapper.java.classpath.32=3Dworkforce\libs\velocity\lib\commons-collect=
ions.jar=20
>
> wrapper.java.classpath.33=3Dworkforce\libs\httpunit\lib\httpunit.jar
> wrapper.java.classpath.34=3Dworkforce\libs\httpunit\lib\Tidy.jar
> wrapper.java.classpath.35=3Dworkforce\libs\xalan-j\xalan.jar
> wrapper.java.classpath.36=3Dworkforce\libs\xalan-j\xml-apis.jar
> wrapper.java.classpath.37=3Dworkforce\libs\xalan-j\xercesImpl.jar
> wrapper.java.classpath.38=3Dworkforce\libs\Actuate\ACJDesigner.jar
> wrapper.java.classpath.39=3Dworkforce\libs\Actuate\ACJMain.jar
> wrapper.java.classpath.40=3Dworkforce\libs\Actuate\ACJRuntime.jar
> wrapper.java.classpath.41=3Dworkforce\libs\Actuate\erdj9xl.jar
> wrapper.java.classpath.42=3Dworkforce\libs\Actuate\PDFExt.jar
> wrapper.java.classpath.43=3Dworkforce\libs\Actuate\ReportDesignerHelp.j=
ar
> wrapper.java.classpath.44=3Dworkforce\libs\xfunction\xFunction.jar
> wrapper.java.classpath.45=3Dworkforce\libs\wrapper\wrapper.jar
> wrapper.java.classpath.46=3Dworkforce\libs\quartz1.0.3b3\commons-collec=
tions.jar=20
>
> wrapper.java.classpath.47=3Dworkforce\libs\quartz1.0.3b3\commons-dbcp.j=
ar
> wrapper.java.classpath.48=3Dworkforce\libs\quartz1.0.3b3\commons-loggin=
g.jar=20
>
> wrapper.java.classpath.49=3Dworkforce\libs\quartz1.0.3b3\commons-pool.j=
ar
> wrapper.java.classpath.50=3Dworkforce\libs\quartz1.0.3b3\quartz.jar
> wrapper.java.classpath.51=3Dworkforce\libs\dom4j\dom4j-full.jar
> wrapper.java.classpath.52=3Dworkforce\libs\fop\fop.jar
> #wrapper.java.classpath.1=3DC:\bin\wrapper.jar
>
> # Java Library Path (location of Wrapper.DLL or libwrapper.so)
> wrapper.java.library.path.1=3DD:\Workforce\Prod\4.1.1\workforce\libs\wr=
apper=20
>
>
> # Java Additional Parameters
> wrapper.java.additional.1=3D-Dconfiguration_file=3DD:\Workforce\Prod\4.=
1.1/config_scheduler.xml=20
>
>
> wrapper.java.additional.2=3D-Dsun.rmi.dgc.server.gcInterval=3D0x7ffffff=
fffffffff=20
>
> wrapper.java.additional.3=3D-Dsun.rmi.dgc.client.gcInterval=3D3600000
> wrapper.java.additional.4=3D-Xms256m
> wrapper.java.additional.5=3D-Xmx800M
> wrapper.java.additional.6=3D-XX:MaxNewSize=3D500m
> wrapper.java.additional.7=3D-XX:NewRatio=3D3
> wrapper.java.additional.8=3D-XX:SurvivorRatio=3D3
> wrapper.java.additional.9=3D-XX:+PrintTenuringDistribution
> wrapper.java.additional.10=3D-Djava.rmi.server.codebase=3Dfile:/classes=

>
> # Initial Java Heap Size (in MB)
> wrapper.java.initmemory=3D25
>
> # Maximum Java Heap Size (in MB)
> wrapper.java.maxmemory=3D100
>
> # Application parameters.  Add parameters as needed starting from 1
> # main class to start:
> wrapper.app.parameter.1=3Dcom.workforcesoftware.scheduler.SchedulerServ=
ice
> #wrapper.app.parameter.2=3D2000
>
> # Port which the native wrapper code will attempt to connect to
> wrapper.port=3D1778
>
> #********************************************************************
> # Wrapper Logging parameters
> #********************************************************************
> # 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=3DERROR
>
> # Log file to use for wrapper output logging.
> wrapper.logfile=3DD:\Workforce\Prod\4.1.1\logs\SchedulerWrapper.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=3DDEBUG
> wrapper.logfile.loglevel=3DERROR
>
> # 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=3D10m
>
> # 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=3D10
>
> # Log Level for sys/event log output.  (See docs for log levels)
> wrapper.syslog.loglevel=3DERROR
>
> #********************************************************************
> # Wrapper Unix daemon parameters
> #********************************************************************
> # File to write process ID to
> wrapper.pidfile=3D/var/run/testwrapper.pid
>
> #********************************************************************
> # Wrapper NT Service parameters
>
> #********************************************************************
> # WARNING - Do not modify any of these parameters 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=3DWorkforce Schd Prod Version 4.1.1
>
> # Display name of the service
> wrapper.ntservice.displayname=3DWorkforce Scheduler Prod Version 4.1.1
>
> # Description of the service
> wrapper.ntservice.description=3DWorkforce Scheduler Prod Version 4.1.1
>
> # Service dependencies.  Add dependencies as needed starting from 1
> wrapper.ntservice.dependency.1=3D
> wrapper.ntservice.dependency.2=3D
>
> # Mode in which the service is installed.  AUTO_START or DEMAND_START
> wrapper.ntservice.starttype=3DDEMAND_START
>
> # Priority at which the service is run.  NORMAL, LOW, HIGH, or
> #  REALTIME
> wrapper.ntservice.process_priority=3DNORMAL
>
>
> Thanks,
> Krishna