[JAVA] Folgen Sie einem mysteriösen Ereignis, bei dem sich die Protokollstufe plötzlich ändert - ein Tag eines OSS-Supporttechnikers

Einführung

** Es liegt ein Problem mit dem folgenden Java-Code vor. Wissen Sie, wo das Problem liegt? ** ** **

    Logger.getLogger("test").setLevel(Level.OFF);

Dies ist ein Code, der die Protokollausgabe für einen Protokollierer mit dem Namen "test" unterdrücken soll.

Der hier verwendete Logger ist der Java-Standard java.util.logging.Logger, und dergetLogger ()gibt eine Logger-Instanz mit dem im Argument angegebenen Namen zurück, falls sie bereits erstellt wurde. Ist eine neu generierte Methode. setLevel () legt die Protokollstufe für diesen Logger fest. Das Argument lautet "Level.OFF". Deaktivieren Sie daher die Protokollausgabe.

Dieser Artikel ist eine wahre Geschichte über das Problem, das durch den obigen Code verursacht wird.

Probleme, die durch diesen Code verursacht werden

Eines Tages kam eine dringende Ermittlungsanfrage zu mir. Der Inhalt lautete: "Der Neustart von Tomcat hat die Webanwendung dazu veranlasst, eine normale Antwort ohne Text zurückzugeben." Obwohl das Ereignis nach dem Neustart nicht wieder aufgetreten ist, möchte ich Sie bitten, die Ursache zu untersuchen, um sich auf die Zukunft vorzubereiten.

Rausfinden

Die Untersuchung begann also sofort. Wenn das gemeldete Ereignis wahr ist, sollte im Zugriffsprotokoll von Tomcat eine Zeile ähnlich der folgenden angezeigt werden:

192.169.1.8 ...(Abkürzung)TP ･ ･ HTTP/1.1" 200 - 379 PostmanRuntime/7.1.3

Die "Zeile wie diese" bedeutet, dass nach der HTTP-Version (in diesem Beispiel "HTTP / 1.1") "200" den Statuscode der normalen Antwort angibt und die Größe des Antwortkörpers 0 ist. Dies ist die Zeile gefolgt von "-" [^ 1].

Als ich das Zugriffsprotokoll unter dieser Bedingung durchsuchte, gab es sicherlich viele zutreffende Zeilen. Alle von ihnen sind nur Zugriffsprotokolle auf eine bestimmte URL zwischen dem Neustart von Tomcat, bei dem das Auftreten des Ereignisses bestätigt wurde, und dem nächsten Neustart. Bei weiteren Untersuchungen wurde festgestellt, dass zur gleichen Zeit wie das Ereignis auch eine "NullPointerException" auftrat. Der Ort, an dem "NullPointerException" auftrat, war die folgende Methode der Klasse "LogFilter" von Restlet [^ 2], die intern von der Webanwendung verwendet wurde. Wie Sie sehen können, handelt es sich nur um eine Methode, die ein INFO-Level-Protokoll ausgibt.

java:org.restlet.engine.log.LogFilter

protected void afterHandle(Request request, Response response) {

	if ((request.isLoggable()) && (this.logLogger.isLoggable(Level.INFO))) {
		//★★ NPE trat in der nächsten Zeile auf ★★
		long startTime = ((Long)request.getAttributes().get("org.restlet.startTime")).longValue();
		int duration = (int)(System.currentTimeMillis() - startTime);
		this.logLogger.log(Level.INFO, this.logService.getResponseLogMessage(response, duration));
	}
}

Als Ergebnis der Untersuchung wurde festgestellt, dass das Auftreten von "NullPointerException" und die daraus resultierende normale Reaktion ohne Text durch den Restlet-Fehler verursacht werden [^ 3]. Wir haben auch festgestellt, dass die obige Methode immer aufgerufen wird, wenn auf die URL zugegriffen wird, unter der das Ereignis aufgetreten ist. Eine Sache, die ich nicht verstand, blieb jedoch bestehen.

Das Geheimnis ging

Das heißt, ** der Code in der obigen if-Anweisung ist effektiv toter Code in einer Webanwendung **. Mit anderen Worten, es kann nicht in diese Verzweigungsbedingung aufgenommen werden.

Dies liegt daran, dass der Quellcode der Webanwendung so implementiert wurde, dass der bedingte Ausdruck "this.logLogger.isLoggable (Level.INFO))" immer "false" ist. In Webanwendungen ist es seit langem ein Problem, dass eine große Anzahl von Restlet-Protokollen in "Catalina.out" (Tomcats Protokoll) ausgegeben wird und Maßnahmen ergriffen wurden, um die Ausgabe zu deaktivieren.

Die Gegenmaßnahmen waren wie folgt.

ServiceEndpointApplication (die Klasse, die der Startpunkt für den Restlet-Aufruf einer Webanwendung ist)

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static {
         Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
         logger.setLevel(Level.OFF);
     }

Der gleiche Prozess zur Ungültigmachung der Protokollausgabe wie zu Beginn beschrieben wird im statischen Initialisierer der Klasse "ServiceEndpointApplication" der Webanwendung implementiert.

Der "LogFilter" von Restlet enthält eine Logger-Instanz für "Restlet" im Feld. Daher setzt die "ServiceEndpointApplication", die immer unmittelbar vor dem Aufruf dieser Klasse aufgerufen wird, die Protokollstufe auf "OFF" und unterdrückt die Protokollausgabe. Die Absicht dieser Maßnahme ist es, dies zu tun. In der Webanwendung habe ich Restlet nur eingeschränkt verwendet, daher war es meines Erachtens ein Urteil, dass "es kein Problem gibt, auch wenn Sie das Restlet-Protokoll nicht ausgeben".

Mit dieser Gegenmaßnahme ist die Protokollebene "AUS", daher sollte sie nicht früher in den Zweig der if-Anweisung eingegeben werden, sondern in Wirklichkeit in den Zweig und es ist eine "NullPointerException" aufgetreten. Noch seltsamer ist, dass dies nie passiert ist, obwohl ich Tomcat in der Vergangenheit viele Male neu gestartet habe. Durch einen Neustart von Tomcat nach dem Eintreten des Ereignisses konnte das Ereignis überhaupt nicht reproduziert werden.

Warum hat sich die Protokollstufe geändert?

Das erste, was Sie vermuten, ist, dass Sie einige Dateien haben, die die Protokollstufe beim Neustart ändern. Beispielsweise wurde möglicherweise die War-Datei einer älteren Version der Webanwendung bereitgestellt oder eine Eigenschaftendatei hinzugefügt, um die Protokollstufe zu ändern.

Als ich mich jedoch bei der verantwortlichen Person erkundigte, war die Antwort, dass der Neustart automatisiert und sehr unwahrscheinlich war. Angesichts der Tatsache, dass das Ereignis nach dem Neustart nach dem Eintreten des Ereignisses nicht reproduziert wurde, ist es sicherlich unwahrscheinlich, dass eine Datei eingemischt wurde (wenn die Datei nicht wiederhergestellt wird, tritt das Ereignis danach auf). Weil ich weitermachen werde).

In jedem Fall ist es schwierig zu untersuchen, ob das Ereignis nicht reproduziert werden kann. Deshalb habe ich beschlossen, zu prüfen, ob es in der lokalen Umgebung reproduziert werden kann. Da ich die Anforderung (URL) identifizieren konnte, bei der das Ereignis auftritt, habe ich sie an die Webanwendung gesendet und geprüft, ob sie reproduziert werden kann, aber überhaupt nicht. Selbst in der Umgebung, in der das Ereignis aufgetreten ist, ist die Inzidenzrate so hoch, dass sie erst nach einem Neustart eines Tages auftrat. Daher sollte sie nicht einfach reproduziert werden können, und es wird angenommen, dass einige Bedingungen vorliegen.

Und nach Versuch und Irrtum konnte ich das Ereignis endlich reproduzieren. Wenn eine große Anzahl von Anforderungen unmittelbar nach dem Neustart mit JMeter in mehreren Threads gesendet wurde, wurde sie mit einer Wahrscheinlichkeit von etwa einmal alle fünf Male reproduziert. Mit anderen Worten, mit den oben genannten Gegenmaßnahmen für Webanwendungen stimmt etwas nicht.

Fehlfunktion beim Multithreading?

Ich vermute eine Multithread-Fehlfunktion, aber ich muss wissen, warum die Protokolle vorher nicht ausgegeben werden. Dafür gibt es zwei erste mögliche Gründe.

1. Irgendwo nach diesem statischen Initialisierer wird setLevel () aufgerufen
2. Erstens wird setLevel () nicht aufgerufen

Zuerst greife ich den Quellcode der Webanwendung und Restlet mit dem Schlüsselwort "setLevel", um zu überprüfen, ob der erste Grund korrekt ist. Ich konnte jedoch keinen Code finden, der dies verursachen könnte. Es ist unwahrscheinlich, dass Sie "setLevel ()" in einer anderen Webanwendung und einem anderen Quellcode als "Restlet" aufrufen. Dies scheint also nicht der Grund zu sein.

Um zu überprüfen, ob der zweite Grund korrekt ist, habe ich beschlossen, diesem statischen Initialisierer eine Anweisung "System.out.println ()" hinzuzufügen und den Vorgang zu überprüfen.

Mit anderen Worten, das ist es.

ServiceEndpointApplication (die Klasse, die der Startpunkt für den Restlet-Aufruf einer Webanwendung ist)

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static {
         System.out.println("ServiceEndpointApplication#clinit start");
         Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
         logger.setLevel(Level.OFF);
         System.out.println("ServiceEndpointApplication#clinit end");
     }

Hier erfahren Sie, ob diese Klasse nicht geladen ist oder ob im statischen Initialisierer für Multithreading Ausnahmen (Fehler) vorhanden sind.

Das Ergebnis der Ausgabe bei der Wiedergabe des Ereignisses war jedoch wie folgt.

ServiceEndpointApplication#clinit start
ServiceEndpointApplication#clinit end

Mit anderen Worten, es ist sicher, dass es auf "Level.OFF" eingestellt ist. Weder der erste noch der zweite Grund scheinen richtig zu sein.

Laufen in einem anderen Klassenlader?

In diesem Fall verwendet Restlet möglicherweise keine von der Webanwendung vorgenerierte Protokollierungsinstanz (mit ungültiger Protokollstufe), z. B. weil sie von einem anderen Klassenladeprogramm initialisiert wurde.

Also habe ich die folgenden Korrekturen vorgenommen und versucht, die Reproduktion erneut zu bestätigen. Der Name und die ID der Logger-Instanz sowie die Informationen des geladenen Klassenladeprogramms werden an dem Ort ausgegeben, an dem die Logger-Instanz zuerst generiert wird, und an dem Ort, an dem sie erfasst und in das Protokoll ausgegeben wird.

ServiceEndpointApplication (die Klasse, die der Startpunkt für den Restlet-Aufruf einer Webanwendung ist)

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static {
        Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
        logger.setLevel(Level.OFF);
		System.out.println("ServiceEndpointApplication#clinit");
		System.out.println("-------------------------------------");
		System.out.println("Logger Name: " + logger.getName());
		System.out.println("Logger Instance ID: " + logger);
		System.out.println("Class Loader: " + Thread.currentThread().getContextClassLoader());
     }

java:org.restlet.engine.log.LogFilter

protected void afterHandle(Request request, Response response) {

	System.out.println("LogFilter#afterHandle");
	System.out.println("-------------------------------------");
	System.out.println("Logger Name: " + logger.getName());
	System.out.println("Logger Instance ID: " + logger);
	System.out.println("Class Loader: " + Thread.currentThread().getContextClassLoader());
	if ((request.isLoggable()) && (this.logLogger.isLoggable(Level.INFO))) {
		long startTime = ((Long)request.getAttributes().get("org.restlet.startTime")).longValue();
		int duration = (int)(System.currentTimeMillis() - startTime);
		this.logLogger.log(Level.INFO, this.logService.getResponseLogMessage(response, duration));
	}
}

Die Ausgabe sieht folgendermaßen aus:

ServiceEndpointApplication#clinit
-------------------------------------
Logger Name: org.restlet.Component.LogService
Logger Instance ID: java.util.logging.Logger@1051f7a6
Class Loader: WebappClassLoader
  context: /Webapp1
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@2d3b52e

LogFilter#afterHandle: 
-------------------------------------
Logger Name: org.restlet.Component.LogService
Logger Instance ID: java.util.logging.Logger@b5270f5
Class Loader: WebappClassLoader
  context: /Webapp1
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@2d3b52e

Das Ergebnis zeigt, dass die Logger-Klassen vom selben Klassenladeprogramm geladen werden, jedoch unterschiedliche Instanzen sind. Dies kann bedeuten, dass die einmal erstellte Logger-Instanz zerstört und neu erstellt wurde.

Andere Möglichkeiten?

Anstatt also Javadoc von java.util.logging.Logger.getLogger () zu starten Ich habe beschlossen, .html # getLogger-java.lang.String-) zu überprüfen. Und ich fand die folgende Beschreibung.

Hinweis: LogManager kann nur schwache Verweise auf neu erstellte Logger enthalten. Es ist wichtig zu verstehen, dass ein zuvor mit dem angegebenen Namen erstellter Logger jederzeit ohne großen Verweis auf den Logger Müll gesammelt werden kann. Dies sind insbesondere zwei aufeinanderfolgende Aufrufe, z. B. getLogger ("MyLogger"). Log (...) und "MyLogger", wenn an keiner Stelle im Programm ein starker Verweis auf einen Logger mit dem Namen "MyLogger" vorhanden ist. Dies bedeutet, dass ein anderes Logger-Objekt mit dem Namen verwendet werden kann.

Mit anderen Worten, wenn GC in einer kurzen Zeit (sogar 1 Millisekunde) zwischen dem Aufruf des statischen Initialisierers von "ServiceEndpointApplication" und dem Aufruf von "LogFilter # afterHandle ()" auftritt, wird "Logger.getLogger" () `Kann eine andere Instanz sein, und die Protokollstufe, die Sie festgelegt haben sollten, ist die Standardeinstellung.

Wenn GC innerhalb dieser kurzen Zeit nicht auftritt, wird die Logger-Instanz danach in der Restlet-Klasse beibehalten (= stark referenziert), sodass sie nicht für immer GC unterliegt (es sei denn, sie wird neu gestartet). .. Deshalb haben die Neustarts, die ich so oft durchgeführt habe, das Ereignis nur einmal verursacht.

Überprüfen Sie den Betrieb

Wenn Sie versuchen, diesen Vorgang mit einem einfachen Programm zu reproduzieren, ist dies wie folgt.

	public static void main(String[] args) {
		Logger.getLogger("test").setLevel(Level.OFF);
		//Wenn hier GC auftritt,
		System.gc();
		//Danach getLevel()Gibt null zurück.
		System.out.println(Logger.getLogger("test").getLevel());
	}

Das Ergebnis ist "null". Wenn Sie "System.gc ();" auskommentieren und während dieser Zeit kein GC auftritt, wird es als "OFF" ausgegeben.

Ich sehe häufig Code, der einen Logger aus einem bestimmten Grund auf eine Feldvariable wie die folgende setzt (um zu verhindern, dass GC die für eine Instanz festgelegten Attribute verliert):

    public static Logger logger = Logger.getLogger("xxx.xxx");

Ändern wir also den Quellcode. Wäre es wie folgt, wenn nur die minimale Korrektur vorgenommen würde?

ServiceEndpointApplication (die Klasse, die der Startpunkt für den Restlet-Aufruf einer Webanwendung ist)

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static Logger;
     static {
         logger = Logger.getLogger(RESTLET_LOGGER_NAME);
         logger.setLevel(Level.OFF);
     }

Nachdem ich dieses Update angewendet hatte, versuchte ich 20 Mal, den Vorgang mit dem gefundenen Reproduktionsverfahren zu überprüfen, aber dieses Ereignis trat nicht auf. Da die Rückrufrate ungefähr alle 5 Mal war, kann gesagt werden, dass es kein Problem gibt, wenn sie nicht reproduziert wird, selbst wenn sie 20 Mal durchgeführt wird ($ \ scriptsize {(1 - 0,8 ^ {20}) * 100 ≒ 99 \ %} $ Ich bin sicher).

Schließlich

Ich werde die erste Frage noch einmal beantworten.

    Logger.getLogger("test").setLevel(Level.OFF);

Dieser Code kann nicht garantieren, dass die Protokollausgabe für einen Protokollierer mit dem Namen "test" unterdrückt wird. Mit anderen Worten, die Chancen für den nächsten Test der Methode "info ()" sind ungleich Null.

    Logger.getLogger("test").setLevel(Level.OFF);
    //Wenn hier GC auftritt, Logger.getLogger()Gibt eine andere Instanz zurück
    Logger.getLogger("test").info("test!");

[^ 1]: Um genau zu sein, hängt es vom Ausgabeformat des Tomcat-Zugriffsprotokolls ab. In dieser Umgebung war dies das Standardausgabeformat. [^ 2]: Restlet ist ein OSS-Framework zum Erstellen von RESTfull-Webanwendungen. [^ 3]: Dieses Commit wurde behoben. Wie man es repariert ist nicht gut, aber ...