Merkwürdiger Fehler: Applikation hängt einfach, Quartz-bug?

[jollyroger]

Hallo zusammen,

ich hab hier einen Fehler, der es locker auf meine persönliche Top 3 Liste der merkwürdigsten Fehler schafft...

Ich versuche mich kurz zu fassen:

- Ich habe eine Servlet-Applikation in der Version 1.0. Diese ist spring-konfiguriert und wird über ant als war-file gepackt.
In dieser Applikation starte ich über das quartz-framework diverse jobs.
- Diese läuft sowohl auf meinem Testsytem als auch auf meinen Produktivsystemen.
- Nun hab ich Version 1.1 fertiggestellt
- Diese läuft nur auf meinem Testsytem jedoch __nicht__ auf meinen Produktivsystemen.
- Der Fehler:

Ja, das ist das Problem. Es gibt keinen Fehler. Die Applikation "hängt" einfach, weder über log4j noch über catalina.out gibt es irgendwelche Fehlermeldungen / exceptions.

Die relevante Codestelle (die "unsinnigen" Logmeldungen wurden nachträglich eingefügt um auf den Produktiv-Systemen nachzuvollziehen wo es hängt):

Mein Servlet wird per Tomcat-Direktive "load-on-startup" gestartet, die init() sieht so aus:

	public void init(){	    
                ApplicationContext ctx = WebApplicationContextUtils.getWebApplicationContext(getServletContext());
		this.jobStarter = (JobStarter) ctx.getBean("JobStarter");
		this.outPrinter = (OutPrinter) ctx.getBean("OutPrinter");
		initLogging();
		startJobs();
	}

Ganz zum Schluß wird startJobs() aufgerufen:

	private void startJobs() {

		logger.info("vor 'startJobs()' ......");
		jobStarter.startJobs();
		logger.info("nach 'startJobs()'!");
	}

Die startet (Überraschung.... nun meine Jobs:

	public void startJobs() {
		
		logger.info("entered startJobs()....");
		SchedulerFactory schedulerFactory = new org.quartz.impl.StdSchedulerFactory();
		logger.info("SchedulerFactory schedulerFactory = new org.quartz.impl.StdSchedulerFactory();");
		Scheduler scheduler = null;
		try {
			scheduler = schedulerFactory.getScheduler();
			logger.info("scheduler = schedulerFactory.getScheduler();");
		} catch (SchedulerException e) {
			logger.info("SchedulerException!");
			logger.fatal(e.getMessage());
			logger.fatal(e);
		}
			
		/*
		 * filemon
		*/
		logger.info("Before: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'");		
		JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);
		logger.info("After: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'");

Eine "normale" log-Ausgabe auf meinem Testsystem sieht nun so aus:

INFO (Sender.initLogging) 2007-06-27 11:24:24,930
 LOGGING_INITIALIZED
INFO (Sender.initLogging) 2007-06-27 11:24:24,934
 initLogging wird verlassen......
INFO (Sender.startJobs) 2007-06-27 11:24:24,934
 vor 'startJobs()' ......
INFO (JobStarter.startJobs) 2007-06-27 11:24:24,935
 entered startJobs()....
INFO (JobStarter.startJobs) 2007-06-27 11:24:24,953
 SchedulerFactory schedulerFactory = new org.quartz.impl.StdSchedulerFactory();
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,035
 scheduler = schedulerFactory.getScheduler();
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,035
 Before: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,046
 After: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,057
 vor scheduler-aufrufen......
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,059
 INFO_ALL_JOBS_SCHEDULED
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,061
 INFO_ALL_JOBS_STARTED
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,063
 nach scheduler-aufrufen!
INFO (Sender.startJobs) 2007-06-27 11:24:25,064
 nach 'startJobs()'!

Auf meinem Produktivsystem sieht es hingegen so aus:

INFO (Sender.initLogging) 2007-06-26 14:36:18,001
 LOGGING_INITIALIZED
INFO (Sender.initLogging) 2007-06-26 14:36:18,012
 initLogging wird verlassen......
INFO (Sender.startJobs) 2007-06-26 14:36:18,015
 vor 'startJobs()' ......
INFO (JobStarter.startJobs) 2007-06-26 14:36:18,017
 bin in startJobs!!!
INFO (JobStarter.startJobs) 2007-06-26 14:36:18,111
 SchedulerFactory schedulerFactory = new org.quartz.impl.StdSchedulerFactory();
INFO (JobStarter.startJobs) 2007-06-26 14:36:19,216
 scheduler = schedulerFactory.getScheduler();
INFO (JobStarter.startJobs) 2007-06-27 11:24:25,035
 Before: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'

Wie an den Debug-Ausgaben zu sehen ist, kommt die Applikation bis hierhin

		logger.info("Before: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'");

Jedoch nicht mehr bis

 After: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'

Sie hängt also folglich genau an der Zeile:

 JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);

Wie schon gesagt, keine Fehlermeldungen, nichts.

Nun hab ich mir den sourcecode von JobDetail gezogen (aus dem Quartz-Framework) und mir mal angeschaut was bei diesem Konstruktur-Aufruf passiert:

    public JobDetail(String name, String group, Class jobClass) {
        setName(name);
        setGroup(group);
        setJobClass(jobClass);
    }

Alle Methoden-Aufrufe sind stinknormale Setter:

    /**
     * 


     * Set the name of this <code>Job</code>.
     * </p>
     * 
     * @exception IllegalArgumentException
     *              if name is null or empty.
     */
    public void setName(String name) {
        if (name == null || name.trim().length() == 0) {
            throw new IllegalArgumentException("Job name cannot be empty.");
        }

        this.name = name;
    }

    /**
     * 


     * Set the group of this <code>Job</code>.
     * </p>
     * 
     * @param group if <code>null</code>, Scheduler.DEFAULT_GROUP will be used.
     * 
     * @exception IllegalArgumentException
     *              if the group is an empty string.
     */
    public void setGroup(String group) {
        if (group != null && group.trim().length() == 0) {
            throw new IllegalArgumentException(
                    "Group name cannot be empty.");
        }

        if (group == null) {
            group = Scheduler.DEFAULT_GROUP;
        }

        this.group = group;
    }

    /**
     * 


     * Set the instance of <code>Job</code> that will be executed.
     * </p>
     * 
     * @exception IllegalArgumentException
     *              if jobClass is null or the class is not a <code>Job</code>.
     */
    public void setJobClass(Class jobClass) {
        if (jobClass == null) {
            throw new IllegalArgumentException("Job class cannot be null.");
        }

        if (!Job.class.isAssignableFrom(jobClass)) {
            throw new IllegalArgumentException(
                    "Job class must implement the Job interface.");
        }

        this.jobClass = jobClass;
    }

Tja, das sieht doch soweit alles unkritisch aus........

Ich verstehe es nicht, ich habe:

- von V 1.0 zu V1.1 __nichts__ an der Initialisierung geändert, sprich der Code ist identisch geblieben.
- wie kann denn das Ding überhaupt hängen?

Mir ist klar, das mir wahrscheinlich keiner eine direkte Lösung sagen kann, aber für jeden Stupser in die richtige Richtung wäre ich dankbar.........

 

[Gast]

Mal nen clean, hilft nicht immer aber öfters.
Oft ist es so das irgendwelche Sourcen, weis nicht wie es
bei dir ist, voneinander abhängen. Und deshalb nur der Build
teilweise fehlt. Obwohl dann trotzdem nen Fehler kommen sollte.
Versuch mal nen Rebuild.

 

[jollyroger]

Nein,

das hat leider nichts gebracht.........

Noch andere Ideen?

 

[Tobias]

Sind die beiden Systeme identisch?

mpG
Tobias

 

[jollyroger]

Ja,

auf beiden laufen identische Versionen von :

- Tomcat 5.5
- Java JRE 1.5
- Quartz 1.6
- das war-file ist das gleiche wie auf dem Testsystem (sogar die applicationContexte sind gleich)

Test-OS: openSuse 10.2
Produktiv-OS: SLES 9

 

[jollyroger]

Die ganze Sache wird immer mysteriöser:

- ich hab nun mal den Tomcat mit "kill -3" abgeschossen und mir den Stacktrace angeschaut. Was ich merkwürdig finde ist folgender Eintrag:

"DefaultQuartzScheduler_Worker-3" prio=1 tid=0x6b944848 nid=0x1e05 in Object.wait() [0x6c07f000..0x6c0800a0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x689550b0> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:523)
        - locked <0x689550b0> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"DefaultQuartzScheduler_Worker-2" prio=1 tid=0x6b8f5980 nid=0x1e04 in Object.wait() [0x6bd7f000..0x6bd80020]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x68955040> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:523)
        - locked <0x68955040> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

"DefaultQuartzScheduler_Worker-1" prio=1 tid=0x6b8f5c18 nid=0x1e03 in Object.wait() [0x6ba7f000..0x6ba7ffa0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x68954fd0> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:523)
        - locked <0x68954fd0> (a org.quartz.simpl.SimpleThreadPool$WorkerThread)

Was hat das zu bedeuten?

Desweiteren hab ich auch mal eine Klasse von JobDetail abgeleitet, mit debug-Ausgaben versehen und anstelle von JobDetail verwendet:

import org.quartz.JobDetail;

public class TmpJobDetail extends JobDetail {
	
    public TmpJobDetail(String name, String group, Class jobClass) {
    	System.out.println("entered jobdetail constructur!");
    	System.out.println("setting name " + name);
        setName(name);
        System.out.println("setting group " + group);
        setGroup(group);
        System.out.println("setting jobClass " + jobClass);
        setJobClass(jobClass);
        System.out.println("leaving jobdetail constructur!");
    }
}

Das Lustige iist nun:

Auch hier komme ich genau bis

logger.info("Before: 'JobDetail jobDetailFileMonitor = new JobDetail(OutputConstants.JOB_NAME_FILE_MONITOR, null, com.meinarbeitgeber.filetransfer.sft.jobs.JobFileMonitor.class);'");

Tja, nun hab ich wirklich keine Ideen mehr........

Ihr vielleicht?

 

[jollyroger]

So,

das Problem ist gelöst.

Warum ist mir allerdings völlig schleierhaft.

Ich hab mal aus Verzweiflung nach dem Ausschlußprinzip libraries zu $Tomcat_home/common/lib hinzugefügt und hab dann den Übeltäter entdeckt:

Auf einmal benötigt der Tomcat für meine Applikation die lib [commons-collections].jar?!?!

Nach hinzufügen dieser funktioniert alles!

Das erklärt natürlich einige ganz drängende Fragen nicht:

- Ich hab von V1.0 zu V.1.1 __nichts__ an den libs geändert
- Alle Code-Änderungen erfolgten meilenweit von der Initialisierung entfernt
- an allem was mit quartz auch nur annähernd zu tun hatte wurde auch nichts geändert

Wie zum Geier geht sowas bitte schön?
Wie konnte das dann vorher funktionieren?
Wieso bleibt der Tomcat / Quartz was auch immer dann einfach hängen ohne Fehlermeldungen zu werfen?
Wieso braucht Quartz bei gleichbleibendem jar-file auf einmal common-loggings?