Multiplatform 4.1 - Java exception "too many open files

Hello,
I'm still running tests with the 4.1 multi-platform scheduler. The master is running on a Linux RedHat system. Right now there is only one remote agent running on AIX. I've set up one simple job (calling a shel script one-liner on the remote AIX agent).

The job is configured to run every minute (I did this for testing stability). After several hours the remote job suddenly fails and I can find the followinf error in the master's debug log:

2007-09-07 22:40:00,007 [Timer-338] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:40:03,562 [Job #118 - bamacc:testjob] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:41:00,008 [Timer-339] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:41:03,524 [Job #118 - bamacc:testjob] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:42:00,007 [Timer-340] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:42:03,504 [Job #118 - bamacc:testjob] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:43:00,008 [Timer-341] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:43:02,201 [Job #118 - bamacc:testjob] ERROR com.softtreetech.jscheduler.business.log.LoggerImpl - Error generating repo
rts files
java.lang.NullPointerException
at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:831)
at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:813)
at org.apache.velocity.app.VelocityEngine.getTemplate(VelocityEngine.java:470)
at com.softtreetech.jscheduler.business.log.HtmlLogger.o00000(Unknown Source)
at com.softtreetech.jscheduler.business.log.HtmlLogger.generateReportFiles(Unknown Source)
at com.softtreetech.jscheduler.business.log.LoggerImpl.Ã00000(Unknown Source)
at com.softtreetech.jscheduler.business.log.LoggerImpl.addLogRecord(Unknown Source)
at com.softtreetech.jscheduler.business.runner.RemoteJobRunner.runJob(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.oO0000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.Ã00000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl$1.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)
2007-09-07 22:43:03,333 [Job #118 - bamacc:testjob] ERROR com.softtreetech.jscheduler.business.log.LoggerImpl - Error generating repo
rts files
java.lang.NullPointerException
at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:831)
at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:813)
at org.apache.velocity.app.VelocityEngine.getTemplate(VelocityEngine.java:470)
at com.softtreetech.jscheduler.business.log.HtmlLogger.o00000(Unknown Source)
at com.softtreetech.jscheduler.business.log.HtmlLogger.generateReportFiles(Unknown Source)
at com.softtreetech.jscheduler.business.log.LoggerImpl.Ã00000(Unknown Source)
at com.softtreetech.jscheduler.business.log.LoggerImpl.addLogRecord(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.Ã00000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl$1.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)
2007-09-07 22:43:03,334 [Job #118 - bamacc:testjob] ERROR com.softtreetech.jscheduler.business.queue.JobQueue - Couldn't load job
java.io.FileNotFoundException: /opt/scheduler/24x7_Scheduler/Queue/bamacc/3038.q (Too many open files)
at java.io.FileInputStream.open(Native Method)
at java.io.FileInputStream.<init>(FileInputStream.java:106)
at com.softtreetech.jscheduler.business.queue.JobQueue.super(Unknown Source)
at com.softtreetech.jscheduler.business.queue.JobQueue.removeLastJob(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.ÃO0000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.ÃO0000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.Ã00000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl$1.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)
2007-09-07 22:43:03,335 [Job #118 - bamacc:testjob] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:44:00,008 [Timer-342] DEBUG com.softtreetech.jscheduler.business.queue.JobQueue - QUEUE_UNLOCKED
2007-09-07 22:44:01,094 [Job #118 - bamacc:testjob] ERROR com.softtreetech.jscheduler.business.runner.RemoteJobRunner - runJob
java.rmi.ConnectIOException: Exception creating connection to: 172.26.10.1; nested exception is:
java.net.SocketException: Too many open files
at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:587)
at sun.rmi.transport.tcp.TCPChannel.createConnection(TCPChannel.java:185)
at sun.rmi.transport.tcp.TCPChannel.newConnection(TCPChannel.java:171)
at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:94)
at com.softtreetech.jscheduler.business.agent.remote.RemoteAgentImpl_Stub.checkLicense(Unknown Source)
at com.softtreetech.jscheduler.business.runner.RemoteJobRunner.runJob(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.oO0000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.Ã00000(Unknown Source)
at com.softtreetech.jscheduler.business.runner.AbstractJobRunner.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl.execute(Unknown Source)
at com.softtreetech.jscheduler.business.runner.JobExecutorImpl$1.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.net.SocketException: Too many open files
at java.net.Socket.createImpl(Socket.java:388)
at java.net.Socket.<init>(Socket.java:361)
at java.net.Socket.<init>(Socket.java:179)
at sun.rmi.transport.proxy.RMIDirectSocketFactory.createSocket(RMIDirectSocketFactory.java:22)
at sun.rmi.transport.proxy.RMIMasterSocketFactory.createSocket(RMIMasterSocketFactory.java:128)
at sun.rmi.transport.tcp.TCPEndpoint.newSocket(TCPEndpoint.java:569)
... 11 more
2007-09-07 22:44:02,239 [Job #118 - bamacc:testjob] ERROR com.softtreetech.jscheduler.business.log.LoggerImpl - Error generating repo
rts files
java.io.FileNotFoundException: /opt/scheduler/24x7_Scheduler/html_reports/banner.htm (Too many open files)

.... and some more.

When I now try to connect to the web console tomcat's "catalina.out" contains the following error. I'm not able to connect without a complete startover.

******************************************************
* Copyright (C) 2000-2007 SoftTree Technologies, Inc.*
******************************************************
* 24x7 Scheduler Java API v4.1. *
******************************************************
* Unauthorized use or distribution of this program *
* may result in severe civil and criminal penalties, *
* and will be prosecuted to the maximum extent *
* possible under the law. *
******************************************************

IOException in sendMessage(): java.net.SocketException: Broken pipe

java.net.SocketException: Broken pipe
IOException while running socketReader: java.io.EOFException
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:115)
at java.io.DataOutputStream.writeInt(DataOutputStream.java:181)
at com.sybase.dpb.JDPB_Connection.sendMessage(JDPB_Connection.java:602)
at com.sybase.dpb.JDPB_Connection.connect(JDPB_Connection.java:444)
at com.sybase.dpb.JDPB_Connection.connect(JDPB_Connection.java:324)
at com.jwi24x7.ConnectorWrapper.connect(ConnectorWrapper.java:45)
at org.apache.jsp.login_005fproceed_jsp._jspService(login_005fproceed_jsp.java:79)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:94)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:324)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:292)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:236)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:152)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:799)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:705)
at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:577)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:595)
java.io.EOFException
IOException in sendMessage(): java.net.SocketException: Broken pipe
at java.io.DataInputStream.readInt(DataInputStream.java:358)
at com.sybase.dpb.AsyncSocketReader.run(AsyncSocketReader.java:41)

This is the second time I encoutered this problem. I have no idea what may cause this error.
Can you help?

Thanks in advance.

I just found out (with lsof) that the java process jscheduler.jar opens the file "velocity.log" over and over again. After running the master for just 10 minutes this files is opened 30 times and still growing. Looks like a bug for me.

Any hints?

Thanks in advance.

Update : Master is running 30 minutes -> velocity.log is opened 120 times.

Next update : No difference between build 242 and 245 - growing open velocity.log files.

This is a known bug in velocity component used internally by Apache log4j logger service, which is integrated with 24x7. This problem is actually platform dependent and appears only on certain system types. I believe the solution is upgrade to a different component version for the logger. I will try to find out for you where to get another version of this component.

Thanks for this information.
Please let me know if I can do something to get around this problem. Until the problem is not solved I'm not able to use the multiplatform edition in our productive environment because it's not acceptable for us to restart the master every 1 or 2 hours.
Any further information/hint is appreciated.

Thanks for your support.

There appears to be no simple solution to this issue. This actual solution may very depending on the settings and the operation system type. You may need to increase max files parameter for the OS system or the logger process.

Please try disabling HTML status reports option and tracing option and check if you can reproduce the problem with "too many files open" Let's us know it these options make any difference.

When I switch off HTML-reports the problem disappeared. How do we continue?
Do you have more ideas I can try? Running the master on another OS? Other JAVA enironment?

Pushing the open file limit is no solution. Standard limit is now 1024 which is reached after ~ 12 hours. I can see no sense to raise the limit. Setting it to 10000 would lead to a deadlock after 5 days. I would expect to let the master run continuous.

I just set up a master on AIX with JAVA 1.4.2 - same behavoir with HTML-reporting enabled. I really need a solution for this because it makes no sense for us to run the scheduler without any reporting. We have a team who has to watch and monitor if jobs ran correctly or not and they need a central point of overview to do their job.

We are checking what options are available. I will get back to you shortly on this

We will post a new build later today, which should take care of this issue. Basically, the new build will cache internally used velocity engine rather then reload it on each log file update. This way it will prevent the engine from opening new work files and reuse already opened work file during each log file update.

Thanks a lot for this info.
I'll keep watching the thread.

An email messages with the download link has been sent to the email you used to register with this support board