# java logging api scheint nicht thread save zu sein



## aldi15 (27. Feb 2009)

Hallo zusammen,
ich habe eine Anwendung programmiert, die einen ShutdownHook implementiert. Wenn die Anwendung durch ein kill -15 oder Schließen des Eingabefensters beendet wird, initiiert der Hook einen neuen Thread. In diesem Thread wird die statische Methode einer zweiten Klasse aufgerufen, die einen Flag als Abbruchbedingung für eine Endlosschleife setzt. Soweit läuft alles klar. Die Schleife steigt an der richtigen Stelle aus, so dass ein geregeltes Beenden möglich ist.
Was nicht mehr funktioniert, ist das logging. Ab dem Moment, wo der Thread in der zweiten Klasse die statische Methode ausführt, wird im Hauptthread nichts mehr gelogt. Ich versuche das mal codemäßig zusammenzufassen:

[HIGHLIGHT="Java"]public class Einstiegsklasse{

	 public static void main(String[] args) {	 
		Logging log=new Logging();
		//Hier wird die zweite Klasse initialisiert
		FileSystemHandling FS=new FileSystemHandling(log);		
		addDaemonShutdownHook();		
	}

	//Hier ist der Hook als embedded class
	static protected void addDaemonShutdownHook() {
        Runtime.getRuntime().addShutdownHook(new Thread() {            
            @Override
            public void run() {
                Einstiegsklasse.Shutdown();
            }
        });
    }


	public static void Shutdown() {
        //Hier wird die statische Methode StopSearch der Klasse FileSystemHandling aufgerufen       
        FileSystemHandling.StopSearch();
        try {
            getMainDaemonThread().join();           
        } catch (InterruptedException ex) {
            //log.SetLogmessage("Der abgesicherte Shutdownprozess konnte nicht durchgeführt werden.", enumLoglevel.SEVERE, ex);
        }
    }

}


public class FileSystemHandling{
	Logging mylog;
	boolean	theFlag;
	FileSystemHandling(Logging log){
		mylog=log;
		theFlag=true;
		Hauptmethode();
	}

	//Hier ist die Endlosschleife
	//Die wird tatsächlich abgebrochen, wenn theFlag=false, aber ab dem Zeitpunkt, wo der Thread vom 
	//Shutdown-Hook die Methode StopSearch() ausgeführt hat, wird in der Schleife nichts mehr gelogt!!!!
	Hauptmethode(){
		while(theFlag){
			//Mach was und logge
			mylog.schreibwas("",Level.INFO);
			//Mach nochwas und logge
			mylog.schreibwas("",Level.WARNING);
			//...
		}
	}

	//Hier wird die Abbruchbedingung gesetzt
	public static StopSearch(){
		theFlag=false;
	}
}[/HIGHLIGHT]

Ist das tatsächlich so, daß das Java-logging nicht thread save ist, oder entdeckt jemand einen Fehler im Programm? In der logging api-doc wird auf jeden Fall behauptet, daß die Klasse thread save ist. Sieht allerdings nicht so aus!
Grüße
Albrecht


----------



## ice-breaker (27. Feb 2009)

öhm, das Erste was dein ShutdownHook macht ist StopSearch() aufrufen und somit die Schleife beenden, ergo sobald der Shutdown-Hook ausgeführt wird ist die Schleife zu Ende und es kommen natürlich keine Log-Meldungen mehr.

Kein problem mit threadsave oder nicht (was eh etwas ganz anderes bedeutet) sondern einfach Programmierfehler von dir.


----------



## aldi15 (27. Feb 2009)

Hi icebreaker,


> das Erste was dein ShutdownHook macht ist StopSearch() aufrufen und somit die Schleife beenden


Nee, nee, neee, so einfach ist's nun auch wieder nich 
Also - in dem Augenblick, wo durch den Hook StopSearch() aufgerufen wird, wird der Flag auf false gesetzt, das heißt aber nicht, dass jetzt *sofort *die Schleife beendet wird. Wenn der Flag gesetzt wird, kann sich das Programm sonstwo in der Schleife befinden. Geprüft wird das Schleifenargument erst wieder nach einem kompletten Durchlauf - und dann steigt die Schleife aus, weil theFlag==false! D.h. der ganze Code zwischen dem Zeitpunkt wo der Flag gesetzt wird, bis zum Fuß der Schleife wird noch ausgeführt! Daß dem so ist, kann ich beweisen, denn die Arbeit, die dort getan wird (Bildverarbeitung) wird fertiggestellt! Lediglich das logging funktioniert dann nicht mehr, und zwar ziemlich genau nachdem der Thread vom Hook den Flag gesetzt hat.


> Kein problem mit threadsave oder nicht (was eh etwas ganz anderes bedeutet)


Tatsächlich?


> A piece of code is thread-safe if it functions correctly during simultaneous execution by multiple threads. In particular, it must satisfy the need for multiple threads to access the same shared data, and the need for a shared piece of data to be accessed by only one thread at any given time.


Genau das meinte ich damit. Es scheint, dass das Logging nicht mehr funktioniert, sobald ein anderer Thread (der Hook seine Finger im Spiel hat).
Schöne Grüße
Albrecht


----------



## Ebenius (27. Feb 2009)

Was ist denn Java Logging? Sieht nicht nach Java Util Logging aus.

Ich glaube auch nicht daran, dass es sich um ein Thread-Safety-Problem handelt. Vielmehr könnte ich mir vorstellen, dass das Logging-Zeugs selber einen Shutdown-Hook hat, der die Ströme schließt, oder ähnliches.

Ebenius


----------



## Geeeee (27. Feb 2009)

```
Ein Idee:
[I]Logging log=new Logging();[/I]
log ist "tot" (wenn ich das recht deute), wenn du im ShutdownHook bist
Du solltest NullPointer bekommen beim versuch was zu loggen.
```
Die Aussage war glaube ich totaler Schwachsinn gerade. Ist nur gerade irgendwie das Offensichtlichste, was passieren kann, wenn der ShutdownHook "aktiv" wird.


----------



## Ebenius (27. Feb 2009)

Häng Dir doch mal in die run()-Methode der java.lang.ApplicationShutdownHooks-Klasse einen Brechpunkt und Guck was beim Beenden so alles passiert.

Viel Erfolg!
Ebenius


----------



## aldi15 (27. Feb 2009)

Hi Ebenius,
wie ich sehe, hast du dein Bild wieder . 
Doch, das ist java.util.Logging. Ich hab's nur in eine eigene Klasse gepackt der Bequemlichkeit wegen. Ist also eher als Pseudocode zu sehen. 
Tja , ich würde das Programm ja gerne entkäfern mit einem Brechpunkt, weiß aber nicht, wie ich das Programm in der IDE dazu bringe. Schließlich müsste ich dafür ein SIGTERM machen und das innerhalb des Programms. Wenn ich in Netbeans auf den kleinen roten Knopf drücke, steigt das Programm komplett aus. Keine Ahnung, wie ich das simulieren kann.


----------



## Ebenius (27. Feb 2009)

aldi15 hat gesagt.:


> wie ich sehe, hast du dein Bild wieder .


Dazu musste ich mit einflussreichen Menschen schlafen. 



aldi15 hat gesagt.:


> Tja , ich würde das Programm ja gerne entkäfern mit einem Brechpunkt, weiß aber nicht, wie ich das Programm in der IDE dazu bringe.


Einfach in die Main()-Methode das da einfügen: [HIGHLIGHT="Java"]final Thread t = new Thread(new Runnable() {
  public void run() {
    try {
      Thread.sleep(5000); // Zeit musst Du anpassen!
    } catch (Exception ex) {
      ex.printStackTrace();
    }

    System.exit(0);
  }
});
t.setDaemon(true);
t.start();[/HIGHLIGHT]
Code im Browser getippt... Kleine Fehler bitte selbst beheben

Nachtrag: Oder einfach die PID rauswühlen und in der Shell: 
	
	
	
	





```
kill [PID]
```

Ebenius


----------



## ice-breaker (27. Feb 2009)

aldi15 hat gesagt.:


> Nee, nee, neee, so einfach ist's nun auch wieder nich
> Also - in dem Augenblick, wo durch den Hook StopSearch() aufgerufen wird, wird der Flag auf false gesetzt, das heißt aber nicht, dass jetzt *sofort *die Schleife beendet wird. Wenn der Flag gesetzt wird, kann sich das Programm sonstwo in der Schleife befinden. Geprüft wird das Schleifenargument erst wieder nach einem kompletten Durchlauf - und dann steigt die Schleife aus, weil theFlag==false! D.h. der ganze Code zwischen dem Zeitpunkt wo der Flag gesetzt wird, bis zum Fuß der Schleife wird noch ausgeführt! Daß dem so ist, kann ich beweisen, denn die Arbeit, die dort getan wird (Bildverarbeitung) wird fertiggestellt! Lediglich das logging funktioniert dann nicht mehr, und zwar ziemlich genau nachdem der Thread vom Hook den Flag gesetzt hat.


äh, also dein Programm befindet sich in der Schleife gerade direkt hinter den Logging-Befehlen in deinem Code der da noch steckt und das flag wird genau in dem Moment geändert, dementsprechend ist der nächste Schleifendurchlauf direkt abgebrochen wegen dem false-Flag.

Ich verstehe den Sinn von deinem Konstrukt eh nicht, das baut komplett auf das Timing von dem Thread auf, da stimmt schon im Konzept etwas nicht.


----------



## aldi15 (16. Mrz 2009)

> äh, also dein Programm befindet sich in der Schleife gerade direkt hinter den Logging-Befehlen in deinem Code der da noch steckt und das flag wird genau in dem Moment geändert, dementsprechend ist der nächste Schleifendurchlauf direkt abgebrochen wegen dem false-Flag.


OK. nochmal langsam zum mitschreiben:
Ja, ich breche das Programm durch den Flag ab. Ja, nach dem aktuellen Schleifendurchlauf wird das Programm abgebrochen. Soweit ist das allen klar! ABER DARUM GEHT ES GAR NICHT!!!!
Die Hauptarbeit wird in den einzelnen Schritten in der Schleife geleistet. Stell dir einfach vor, dass in der Schleife nochmal zig Zeilen Code abgearbeitet werden. Und mindestens in einer Zeile wird nochmal eine komplexe Verarbeitung in einer anderen Klasse aufgerufen. Um diese Verarbeitungsschritte geht es. An dieser Stelle steht in meinem Code:

```
//Mach was und logge
```
Natürlich wollte ich dem geneigten Leser ersparen, sich durch zig unrelevante Codezeilen zu wühlen. Ich habe einfach etwas Phantasie vorausgesetzt. So was nennt man übrigens Pseudocode.
Das Problem, um das es eigentlich ging war, dass der Code, der in der Schleife bei dem LETZTEN (also aktuellen) Schleifendurchgang NACHWEISLICH abgearbeitet wird. Lediglich das Logging in den Zwischenschritten findet nicht mehr statt. Also plakativ gesprochen (in Pseudocode) :
-Bildverarbeitungsschritt 1
-Logging: "Ich habe Bildverarbeitungsschritt 1 gemacht"
-Bildverarbeitungsschritt 2
-Logging: "Ich habe Bildverarbeitungsschritt 2 gemacht"
-Bildverarbeitungsschritt 3
-Logging: "Ich habe Bildverarbeitungsschritt 3 gemacht"
...
Und das logging dazwischen ist das, was nicht funktioniert, was m.E. nicht nachvollziehbar ist.



> Ich verstehe den Sinn von deinem Konstrukt eh nicht, das baut komplett auf das Timing von dem Thread auf, da stimmt schon im Konzept etwas nicht.


Das kann schon sein, daß du das nicht verstehst. Das heißt aber nicht, daß das Konzept falsch ist. Das Konzept zielt darauf ab, einen Dienst zu erstellen, der ein Dateisystem-polling betreibt. Da brauchst du eben die Schleife und damit sie nicht zuviel Last erzeugt, wird sie getimed. Das ist durchaus übliche Praxis, wenn man auf blackboxed third party-Produkte verzichten möchte und das lieber manuell machen möchte. Das Konzept ist leider nicht von mir persönlich und funktioniert eigentlich (bis auf das beschriebene Problem) sehr gut. Also sonst irgendwelche SACHDIENLICHEN Vorschläge?


----------



## Spacerat (16. Mrz 2009)

Wie wird denn neu gestartet, wenn man mal so dämlich fragen darf? Nicht über "main()"? Das ist schlecht... hast du sowas mal versucht:
	
	
	
	





```
public class FileSystemHandling
{
    Logging mylog = new Logging();
    boolean theFlag;

    FileSystemHandling()
    {
        mylog=log;
        theFlag=true;
        Hauptmethode();
    }

    ...
}
```


----------



## aldi15 (16. Mrz 2009)

> Wie wird denn neu gestartet, wenn man mal so dämlich fragen darf? Nicht über "main()"? Das ist schlecht... hast du sowas mal versucht:


Doch doch, klar Die Einstiegsklasse hat eine public void main. Darüber wird gestartet.


> ... hast du sowas mal versucht:


So wie du das beschreibst könnte man es natürlich machen, aber in der Einstiegsklasse könnte man dann nichts loggen. Nicht so befriedigend.


----------



## KSG9|sebastian (17. Mrz 2009)

Es kommt keine Exception und auch sonst nix? 

Könnte mir nur vorstellen dass der GC anspringt, allerdings ist das sehr unrealistisch. 
Du solltest mal debuggen, v.a. im java.util.Logging, dann siehst du ob evtl. die Config kaputt geht oder so.


----------



## tuxedo (3. Apr 2009)

Wie ist das jetzt ausgegangen? Hab grad gleiches Problem. Hab eine Java Konsolenanwendung (Socket-Server) und ebenfalls einen Shutdown-Hook.

mein run() im shutdown-hook-thread:


[HIGHLIGHT="Java"]public void run() {
        logger.info("shutdown initiated ...");
        System.err.println("1");
        if (authenticator!=null)
            authenticator.shutdown();
        else
            logger.error("authenticator is null!");
        System.err.println("2");
        if (registry!=null) {
            logger.info("unbind servers");
            registry.unbind("communityserver");
            registry.unbind("diagnosisserver");
            logger.info("servers unbound");
        } else
            logger.error("registry is null!");
        System.err.println("3");
        logger.info("shutdown finished. Terminating application!");
        System.err.println("4");
    }[/HIGHLIGHT]

Wie man sehen hab hab ich auch noch Syserr's drin (zum testen). 

Alles was ich auf der Konsole wenn der Shutdownhook greift sehe ist die erste Logausgabe "shutdown initiated ..." und meinen Syserr's. Aber keine der nachfolgenden logger.info oder logger.debug Meldungen. 

Es scheint so, als ob das Java-Logging irgendwie den Shutdown-Hook mitbekommt und sich zentral abschaltet. Getreu dem Motto: "Na beim runterfahren wird die Anwendung 'eh beendet, was will man denn da noch loggen?".

Nun, ich möchte meine User aber beim gewollten runterfahren des Server auf den aktuellen Umstand hinweisen, und da möchte ich nunmal auch noch loggen und mitbekommen ob auch alles sauber geklappt hat.

Any ideas?


----------



## Ebenius (3. Apr 2009)

Das klingt sehr seltsam. Wenn Du Deinen Server kontrolliert herunter fährst, dann musst Du den Shutdown-Prozess doch nicht per Shutdown-Hook steuern...

Egal, der Grund für das beschriebene Problem: 
Der LogManager führt _reset()_ aus einem Shutdown-Hook aus und merkt sich, dass er gerade stirbt (_death imminent_).
Der LogManager unterbindet das Erzeugen neuer Handler, wenn bereits gestorben wird.
ShutdownHooks werden parallel ausgeführt.
Daraus ergibt sich: Kein java.util-Logging in Shutdown-Hooks. That's it.

Ebenius


----------



## maki (3. Apr 2009)

Ein Blick in java.util.logging.LogManager lüftet das Geheimnis:

```
protected LogManager() {
	// Add a shutdown hook to close the global handlers.
        try {
	    Runtime.getRuntime().addShutdownHook(new Cleaner());
        } catch (IllegalStateException e) {
            // If the VM is already shutting down,
            // We do not need to register shutdownHook. 
        }
    }
```
JUL nutzt also auch einen Shutdown Hook.

Da Shudown Hooks laut Doku (Runtime (Java 2 Platform SE 5.0))) nebenläufig ausgeführt werden, ist es wohl keine gute Idee in einem eigenen Shutdown Hook zu versuchen mit JUL zu loggen.

Nachtrag: Verdammt, wieder zu langsam..


----------



## tuxedo (3. Apr 2009)

Danke für die Antworten. Konnte mir das ganze jetzt doch noch selbst erklären (dank dem ersten comment in David Walend's Blog: Shutdown Hooks).

Zum "kontrolliert herunterfahren".

Naja, der Server ist wie gesagt ne Consolenanwendung und läuft in einer "screen" shell. Da beende ich den Server einfach mit ctrl+c.

Anderer "trick" wäre eine Console in meiner Consolenanwendung. Eingeben von "exit" zum herunterfahren oder so. 
Oder eben nen eigenen LogManager der die Logger nicht zu früh beendet.

-Alex


----------



## maki (3. Apr 2009)

Oder log4j


----------



## tuxedo (3. Apr 2009)

Hab eben die "console" eingebaut. Jetzt reicht ein eintippen von "exit"+enter damit alles sauber und "geloggt" runterfährt. ctrl+c geht auch, allerdings nach wie vor ohne logoutput.

- Alex


----------



## Ebenius (3. Apr 2009)

Dazu noch ein Zitat aus der API-Doc von Runtime.addShutdownHook(...): 





> Shutdown hooks run at a delicate time in the life cycle of a virtual machine and should therefore be coded defensively.  They should, in particular, be written to be thread-safe and to avoid deadlocks insofar as possible.  They should also not rely blindly upon services that may have registered their own shutdown hooks and therefore may themselves in the process of shutting down.



Juchuu... Ich hab nen Bug im JDK gefunden... Der Konstruktor der LogManager-Klasse: [HIGHLIGHT="Java"]// Add a shutdown hook to close the global handlers.
try {
    Runtime.getRuntime().addShutdownHook(new Cleaner());
} catch (IllegalStateException e) {
    // If the VM is already shutting down,
    // We do not need to register shutdownHook. 
}[/HIGHLIGHT]
Da muss doch in Zeile 7 noch das da rein, oder? [HIGHLIGHT="Java"]deathImminent = true;[/HIGHLIGHT]
BTW: Man kann dank dieses Fehlers in einem ShutdownHook eine neue Instanz der LogManager-Klasse (bzw. einer nutzlosen Ableitung, da der Konstruktor _protected_ ist) erzeugen, und diese dann zum Loggen benutzen. Am Ende müsste man _reset()_ sagen und vor der Benutzung _readConfiguration()_ aufrufen bzw. den Logger anders konfigurieren. Natürlich müssen auch alle benutzten Logger per _LogManager.getLogger(...)_ von dieser LogManager-Instanz geholt werden. Meiner Meinung nach sollte man aber lieber auf diese Idee verzichten. 

Ebenius


----------



## aldi15 (3. Apr 2009)

Herzlichen Glückwunsch :toll:
Ich kapier die Lösung zwar nicht ganz, aber evtl. muss ich eh das logging nochmal überarbeiten.  Ich finde die Formatierungsmögl. mit JUL zu spartanisch. Wahrscheinlich werde ich meinen Dienst tatsächlich auf log4j umstellen, wenn das Budget das zulässt und damit bin ich dann (hoffentlich) auch das Problem los. Trotzdem - freut mich, dass du den Bug gefunden hast!
Schöne Grüße
Albrecht


----------



## tuxedo (3. Apr 2009)

Wenn du SLF4J dazwischen schnallst bist du was die logging-api angeht ziemlich flexibel ... (hab ich auch so, will aber bei java.logging bleiben).

- Alex


----------



## aldi15 (3. Apr 2009)

Hey, super, das kannte ich noch nicht - danke!
Würde aber auch heißen, daß ich nach wie vor das Problem habe ;(


----------

