Scheduler.logAddMessage - Strange Behaviour

24x7 MP Ver 4.3.293 on Red Hat Linux

I have two jobs (Java Script) which issue the following logAddMessage command(s).

Job A: writes the message to the current "scheduler.log" file (actually the Scheduler seems to be logging all output to scheduler-20100604-121000.log).
Job B: writes the message to a file other than the current "scheduler.log" file, e.g. scheduler-20100604-131201.log

The syntax of the "logAddMessage" code in each job is exactly the same (see below) - which is a puzzle.

I read another post where it was said that the scheduler-yyyymmdd-hhmmss.log files are produced when the scheduler.log file reaches a certain size
as defined by the option "maximumNumberOfLogEntries". I have set this to 99999 (see extract from preferences.xml below);

<property name="loadLogOnStartUp" type="4" value="true"/>
<property name="maximumNumberOfLogEntries" type="1" value="99999"/>
<property name="clearLogOnStartup" type="4" value="false"/>

Another point to note, is that despite the above settings in the preferences.xml file every time i start the 24x7 Scheduler, the Log is cleared !!.
The file Scheduler.log only every contains 1 entry !!

JOB A javascript:
=================
//
// Job Specific values to be defined here.
//
var scriptdir = "/scheduler/scripts/";
var scriptname = "test1.exp";
//
// Calculate the correct value for the logfiles suffix from the current date/time
//
now = new Date();
logsuffix = ""
var suffdate = '@T"yyyymmdd"';
var suffhour = now.getHours();
var suffmin = now.getMinutes();
var suffsec = now.getSeconds();
logsuffix = logsuffix.concat(suffdate,suffhour,suffmin,suffsec);
//
// Build the string to be passed to the runAndWait command.
//
var scriptdir = "/scheduler/scripts/";
var scripttorun = scriptdir + scriptname;
var jobname = '@V"job_name"';
var jobnum = '@V"job_id"';
var logdir = '@T"yyyymmdd"';
var logfile = "/scheduler/logs/" + logdir + "/" + jobname + "." + logsuffix;
//
// Now issue the runAndWait command
//
Scheduler.logAddMessage('INFO',jobnum,jobname,'Running Job = ' + jobname + ', output to ' + logfile);
cmdstring = scriptdir + scriptname + " >> " + logfile;
timeout = 0;
var rwi = Process.runAndWait(cmdstring,0);
//
// Now Save the output from the previous command to logfile.
//
var strOutput = rwi.getOutput();
if ((logfile!=null) && (logfile!="")) {
File.save(logfile,strOutput); // Save the output
}

JOB B javascript:
=================
//
// Job Specific values to be defined here.
//
var scriptdir = "/usr/local/bin/";
var scriptname = "system_status_script.ksh";
//
// Calculate the correct value for the logfiles suffix from the current date/time
//
now = new Date();
logsuffix = ""
var suffdate = '@T"yyyymmdd"';
var suffhour = now.getHours();
var suffmin = now.getMinutes();
var suffsec = now.getSeconds();
if (suffhour <= 9) {suffhour = "0" + suffhour};
if (suffmin <= 9) {suffmin = "0" + suffmin};
if (suffsec <= 9) {suffsec = "0" + suffsec};
logsuffix = logsuffix.concat(suffdate,suffhour,suffmin,suffsec);
//
// Build the string to be passed to the runAndWait command.
//
var jobname = '@V"job_name"';
var jobnum = '@V"job_id"';
var logdir = '@T"yyyymmdd"';
var logfile = "/scheduler/logs/" + logdir + "/" + jobname + "." + logsuffix;
//
// Now issue the runAndWait command
//
Scheduler.logAddMessage('INFO',jobnum,jobname, 'Running Job = ' + jobname + ', output to ' + logfile);
cmdstring = scriptdir + scriptname + " >> " + logfile;
timeout = 0;
var rwi = Process.runAndWait(cmdstring,0);
//
// Now Save the output from the previous command to logfile.
//
var strOutput = rwi.getOutput();
if ((logfile!=null) && (logfile!="")) {
File.save(logfile,strOutput); // Save the output
}

Are you running only 1 instance of the scheduler or more than 1?
Is the scheduler.log file locked by some external process? Does the job user have permissions to write to the scheduler.log file?

I normally run only 1 scheduler instance.
I discovered another running scheduler instance, which i killed :-)
I shutdown the one remaining instance, and verified that there were no other 24x7 instances running.
I started the 24x7 instance (/usr/local/24x7_Scheduler/master.sh nogui &)
The scheduler started writing logs to "/usr/local/24x7_Scheduler/scheduler.log" - so far so good.
I ran one job (JobID=32), which issues a logAddMessage command - the output was written to "/usr/local/24x7_Scheduler/scheduler.log" :-)
I ran another job (JobID=13), which also issues a logAddMessage command....

1. file "scheduler.log" renamed to "scheduler-20100604-155500.log", and this is where output sent to "scheduler.log" is now written.
2. file "scheduler.log" delete/overwritten with the output from the (JOBID=13) logAddMessage

I have added below the status of files in the /usr/local/24x7_Scheduler directory, and their contents which might explain in better detail.
Open scheduler* files are;
/usr/local/24x7_Scheduler : lsof scheduler*
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
java 9615 root 6u REG 253,0 2717 753832 scheduler-20100604-155500.log

-rw-rw-r-- 1 root root 35531 Jun 4 15:50 preferences.bak
-rw-r--r-- 1 root root 185 Jun 4 15:55 scheduler.log
-rw-r--r-- 1 root root 212 Jun 4 15:55 scheduler-20100604-155501.log
drwxrwxr-x 5 root root 4096 Jun 4 15:55 Queue
-rw-rw-r-- 1 root root 35531 Jun 4 15:55 preferences.xml
-rw-r--r-- 1 root root 38987 Jun 4 15:55 debug.log
-rw-r--r-- 1 root root 1013 Jun 4 15:55 scheduler-20100604-155500.log
[root@rhelcs1]
/usr/local/24x7_Scheduler : cat scheduler-20100604-155501.log
4-Jun-2010 03:55:01 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 14 REPORT_CARDCLEAR_LOCALBILLING Running Job = REPORT_CARDCLE AR_LOCALBILLING, output to /scheduler/logs/20100604/REPORT_CARDCLEAR_LOCALBILLING.20100604155501
[root@rhelcs1]
/usr/local/24x7_Scheduler : cat scheduler.log
4-Jun-2010 03:55:01 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 13 REPORT_SYSTEM_STATUS Running Job = REPORT_SYSTEM_STATUS, output to /scheduler/logs/20100604/REPORT_SYSTEM_STATUS.20100604155501
[root@rhelcs1]
/usr/local/24x7_Scheduler : cat scheduler-20100604-155500.log
4-Jun-2010 03:50:23 PM 2 null null 24x7 Scheduler 24x7 Scheduler starting...
4-Jun-2010 03:51:00 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 11 UNIMAT4C1 Job started.
4-Jun-2010 03:51:00 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 11 UNIMAT4C1 Job finished.
4-Jun-2010 03:52:59 PM 2 null null 24x7 Scheduler User root connected from 192.168.1.10
4-Jun-2010 03:53:22 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 32 SCRIPT3 Job started.
4-Jun-2010 03:53:23 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 32 SCRIPT3 Running Job = SCRIPT3, output to /scheduler/logs/201 00604/SCRIPT3.20100604155323
4-Jun-2010 03:53:54 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 32 SCRIPT3 Job finished.
4-Jun-2010 03:55:00 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 14 REPORT_CARDCLEAR_LOCALBILLING Job started.
4-Jun-2010 03:55:00 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 13 REPORT_SYSTEM_STATUS Job started.
4-Jun-2010 03:55:02 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 13 REPORT_SYSTEM_STATUS Job finished.
4-Jun-2010 03:55:13 PM 2 Su/FXUfOyLMie1N52YsbgP8fbIM= 14 REPORT_CARDCLEAR_LOCALBILLING Job finished.

To help further, there are some [FATAL] entries in my "debug.log" file;

2010-06-04 16:00:00,574 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:00:00,574 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:00:00,597 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:00:00,597 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:00:00,597 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3139
2010-06-04 16:00:00,597 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:00:00,597 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:00:00,619 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:00:00,620 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:00:00,620 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3140
2010-06-04 16:00:00,620 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:00:00,620 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:00:00,672 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:00:00,701 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:00:00,707 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:00:00,892 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:00:00,936 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:00:00,988 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:00:00,994 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:00:01,061 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:00:01,156 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:00:01,303 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : Premature end of file.
2010-06-04 16:00:01,304 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : Setting shutdown event hook
2010-06-04 16:00:01,305 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : loading job db
2010-06-04 16:00:01,306 [main] FATAL com.softtreetech.jscheduler.JSchedulerStarter - startup() :
java.lang.IllegalStateException: pref db is not opened.
at com.softtreetech.jscheduler.business.preferences.AbstractPrefDatabase.new(Unknown Source)
at com.softtreetech.jscheduler.business.preferences.AbstractPrefDatabase.getIdsByType(Unknown Source)
at com.softtreetech.jscheduler.business.preferences.SettingsImpl.o00000(Unknown Source)
at com.softtreetech.jscheduler.business.preferences.SettingsImpl.getLastJobDb(Unknown Source)
at com.softtreetech.jscheduler.ui.OoOO.F.o00000(Unknown Source)
at com.softtreetech.jscheduler.ui.OoOO.OooO.class(Unknown Source)
at com.softtreetech.jscheduler.JSchedulerStarter.o00000(Unknown Source)
at com.softtreetech.jscheduler.JSchedulerStarter.main(Unknown Source)
2010-06-04 16:00:01,309 [main] DEBUG com.softtreetech.jscheduler.business.H - shutdown() start
2010-06-04 16:00:01,309 [main] DEBUG com.softtreetech.jscheduler.business.runner.JobExecutorImpl - killAll() start
2010-06-04 16:00:01,309 [main] DEBUG com.softtreetech.jscheduler.business.H - shutdown() end
2010-06-04 16:05:00,247 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:05:00,248 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:05:00,248 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3144
2010-06-04 16:05:00,248 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:05:00,248 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:05:00,286 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:05:00,401 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:05:00,446 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:10:00,283 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:10:00,284 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:10:00,284 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3146
2010-06-04 16:10:00,284 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:10:00,284 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:10:00,323 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:10:00,406 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:10:00,407 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:10:00,407 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3145
2010-06-04 16:10:00,407 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:10:00,407 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:10:00,440 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:10:00,455 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:10:00,485 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:10:00,587 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:10:00,633 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:10:00,667 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : XML document structures must start and end within the same entity.
2010-06-04 16:10:00,667 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : Setting shutdown event hook
2010-06-04 16:10:00,669 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : loading job db
2010-06-04 16:10:00,669 [main] FATAL com.softtreetech.jscheduler.JSchedulerStarter - startup() :
java.lang.IllegalStateException: pref db is not opened.
at com.softtreetech.jscheduler.business.preferences.AbstractPrefDatabase.new(Unknown Source)
at com.softtreetech.jscheduler.business.preferences.AbstractPrefDatabase.getIdsByType(Unknown Source)
at com.softtreetech.jscheduler.business.preferences.SettingsImpl.o00000(Unknown Source)
at com.softtreetech.jscheduler.business.preferences.SettingsImpl.getLastJobDb(Unknown Source)
at com.softtreetech.jscheduler.ui.OoOO.F.o00000(Unknown Source)
at com.softtreetech.jscheduler.ui.OoOO.OooO.class(Unknown Source)
at com.softtreetech.jscheduler.JSchedulerStarter.o00000(Unknown Source)
at com.softtreetech.jscheduler.JSchedulerStarter.main(Unknown Source)
2010-06-04 16:10:00,670 [main] DEBUG com.softtreetech.jscheduler.business.H - shutdown() start
2010-06-04 16:10:00,670 [main] DEBUG com.softtreetech.jscheduler.business.runner.JobExecutorImpl - killAll() start
2010-06-04 16:10:00,670 [main] DEBUG com.softtreetech.jscheduler.business.H - shutdown() end
2010-06-04 16:15:00,245 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:15:00,245 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:15:00,245 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3148
2010-06-04 16:15:00,245 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:15:00,245 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:15:00,282 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:15:00,396 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:15:00,440 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:20:00,378 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:20:00,378 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:20:00,378 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3149
2010-06-04 16:20:00,378 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:20:00,378 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:20:00,418 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:20:00,426 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - JVM version: 1.5.0_22-b03
2010-06-04 16:20:00,426 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : start
2010-06-04 16:20:00,426 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - main(...) : job on demand: runtime id=3150
2010-06-04 16:20:00,426 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : start
2010-06-04 16:20:00,426 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating business objects
2010-06-04 16:20:00,465 [main] DEBUG com.softtreetech.jscheduler.business.O - System started from /usr/local/24x7_Scheduler/master.sh
2010-06-04 16:20:00,605 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:20:00,607 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : creating UI controller
2010-06-04 16:20:00,650 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects
2010-06-04 16:20:00,659 [main] DEBUG com.softtreetech.jscheduler.JSchedulerStarter - startup() : initializing business objects

Something is still locking the log file. Do you run these jobs using the same user account that you use for the scheduler? If not, can the job user modify existing files in the scheduler directory? I mean user permissions.

Just in case, if user account is not specified in job properties, then the job user is the same as the scheduler user.

I am using the 24x7 Web Console to create/run jobs etc..
I login to the 24x7 Web Console (24x7 Web Console Version 4.3 build 285) with a user called "root" which is an 24x7 Administrator.
I create jobs using this "root" user. The jobs have a "Runs as " status of "Run as root".

Permissions to 24x7 home directory are;
/usr/local/24x7_Scheduler : ls -al
total 16532
drwxrwxr-x 10 root root 20480 Jun 4 16:45 .
drwxr-xr-x 17 root root 4096 Jun 2 11:59 ..

I think I get it now. It looks like you are hitting log file size performance limit. This is not the same thing as number of entries in the log that are used for controlling log rotation. This is the threshold which is used for controlling log usage performance. Basically, when you run a detached job it finds log too big to be efficiently loaded into memory it and starts a new file. To avoid getting into this situation, set these 2 JavaScript jobs to run non-detached. They will be then sharing the log file with the scheduler.

Problem Fixed. :-)

I have changed my jobs to not be detached, and all logAddMessage messages are now going into the main scheduler.log file.