[JAVA] Suivez un événement mystérieux où le niveau de journal change soudainement - Une journée d'ingénieur de support OSS

introduction

** Il y a un problème avec le code Java suivant. Sais-tu quel est le problème? ** **

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

Il s'agit d'un code destiné à supprimer la sortie du journal pour un enregistreur nommé test.

Le Logger utilisé ici est le standard Java java.util.logging.Logger, et legetLogger ()retourne une instance de logger avec le nom donné dans l'argument si elle a déjà été créée. Est une méthode nouvellement générée. setLevel () définit le niveau de journalisation pour cet enregistreur. Puisque l'argument est "Level.OFF", la sortie du journal est désactivée.

Cet article est une histoire vraie sur le problème causé par le code ci-dessus.

Problèmes causés par ce code

Un jour, une demande d'enquête urgente m'est venue. Le contenu était que "Le redémarrage de Tomcat a déclenché l'application Web pour renvoyer une réponse normale sans corps." Bien que l'événement ne soit pas réapparu après le redémarrage, j'aimerais que vous enquêtiez sur la cause en vue de préparer l'avenir.

Trouver

L'enquête a donc commencé immédiatement. Si l'événement signalé est vrai, vous devriez voir une ligne similaire à la suivante dans le journal d'accès de Tomcat:

192.169.1.8 ...(Abréviation)･ ･ ･ HTTP/1.1" 200 - 379 PostmanRuntime/7.1.3

La "ligne comme celle-ci" signifie qu'après la version HTTP ("HTTP / 1.1" dans cet exemple), "200" indique le code d'état de la réponse normale et la taille du corps de la réponse est 0. Il s'agit de la ligne suivie de "-" [^ 1].

Lorsque je grep le journal d'accès dans cette condition, il y avait certainement de nombreuses lignes applicables. Tous ne sont que des journaux d'accès à une URL spécifique entre le redémarrage de Tomcat où l'occurrence de l'événement a été confirmée et le prochain redémarrage. Après une enquête plus approfondie, il a été constaté qu'une «NullPointerException» s'est également produite en même temps que l'événement. L'endroit où NullPointerException s'est produite était la méthode suivante de la classe LogFilter de Restlet [^ 2] utilisée en interne par l'application Web. Comme vous pouvez le voir, c'est juste une méthode qui génère des journaux de niveau ʻINFO`.

java:org.restlet.engine.log.LogFilter

protected void afterHandle(Request request, Response response) {

	if ((request.isLoggable()) && (this.logLogger.isLoggable(Level.INFO))) {
		//★★ NPE se produisait sur la ligne suivante ★★
		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));
	}
}

À la suite de l'enquête, il a été trouvé que l'occurrence de NullPointerException et la réponse normale résultante sans corps sont causées par le bogue Restlet [^ 3]. Nous avons également constaté que la méthode ci-dessus est toujours appelée lors de l'accès à l'URL où l'événement s'est produit. Cependant, une chose que je n'ai pas comprise est restée.

Le mystère est parti

Autrement dit, ** le code de l'instruction if ci-dessus est effectivement du code mort dans une application Web **. En d'autres termes, il ne peut pas être inclus dans cette condition de branche.

En effet, le code source de l'application Web a été implémenté de sorte que l'expression conditionnelle this.logLogger.isLoggable (Level.INFO)) soit toujours false. Dans les applications Web, le fait qu'une grande quantité de journaux Restlet soit sortie vers catalina.out (journal de Tomcat) pose depuis longtemps un problème et des mesures ont été prises pour désactiver la sortie.

Les contre-mesures étaient les suivantes.

ServiceEndpointApplication (la classe qui est le point de départ de l'appel Restlet d'une application Web)

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

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

Le même processus d'invalidation de sortie de journal que décrit au début est implémenté dans l'initialiseur statique de la classe ServiceEndpointApplication de l'application Web.

Le LogFilter de Restlet contient une instance de journalisation pour Restlet dans le champ, donc dans ServiceEndpointApplication qui est toujours appelé juste avant que cette classe soit appelée, le niveau de journalisation est défini sur ʻOFF` et la sortie du journal est supprimée. L'intention de cette mesure est de le faire. Dans l'application Web, je n'ai utilisé Restlet que de manière limitée, donc je pense que c'était un jugement selon lequel "il n'y a pas de problème même si vous ne sortez pas le journal Restlet".

Avec cette contre-mesure, le niveau du journal est «OFF», donc il ne devrait pas entrer dans la branche de l'instruction if plus tôt, mais en réalité il est entré dans la branche et une «NullPointerException» s'est produite. Encore plus étrange, cela ne s'est jamais produit, même si j'ai redémarré Tomcat plusieurs fois dans le passé. Et, en redémarrant Tomcat après que l'événement s'est produit, l'événement n'a pas pu être reproduit du tout.

Pourquoi le niveau de journalisation a changé

La première chose que vous soupçonnez est que vous avez des fichiers qui modifient le niveau de journalisation au redémarrage. Par exemple, le fichier war d'une ancienne version de l'application Web a peut-être été déployé ou un fichier de propriétés a été ajouté pour modifier le niveau de journalisation.

Cependant, lorsque j'ai vérifié avec le responsable, la réponse a été que le processus de redémarrage était automatisé et très improbable. Certes, étant donné que l'événement ne s'est pas reproduit après le redémarrage après l'événement, il semble peu probable qu'un fichier ait été mélangé (si le fichier n'est pas restauré, l'événement se produira après cela). Parce que je vais continuer).

Dans tous les cas, il est difficile d'enquêter si l'événement ne peut pas être reproduit, j'ai donc décidé de vérifier s'il pouvait être reproduit dans l'environnement local. Comme j'ai pu identifier la requête (URL) où se produit l'événement, je l'ai envoyée à l'application Web et j'ai vérifié si elle pouvait être reproduite, mais elle ne s'est pas reproduite du tout. Même dans l'environnement où l'événement s'est produit, le taux d'incidence est tel qu'il ne s'est produit qu'après un redémarrage d'un jour, il ne devrait donc pas être facilement reproduit, et on pense qu'il existe certaines conditions.

Et après essais et erreurs, j'ai finalement pu reproduire l'événement. Lorsqu'un grand nombre de demandes était envoyé dans plusieurs threads à l'aide de JMeter immédiatement après le redémarrage, il était reproduit avec une probabilité d'environ une fois toutes les cinq fois. En d'autres termes, il y a un problème avec les contre-mesures d'application Web mentionnées ci-dessus.

Dysfonctionnement en multithreading?

Je soupçonne un dysfonctionnement multi-thread, mais j'ai besoin de savoir pourquoi les journaux ne sont pas générés avant cela. Il y a deux premières raisons possibles à cela.

1. Quelque part après cet initialiseur statique, setLevel () est appelé
2. En premier lieu, setLevel () n'est pas appelé

Tout d'abord, je grep le code source de l'application Web et Restlet avec le mot-clé "setLevel" pour vérifier que la première raison est correcte. Cependant, je n'ai trouvé aucun code pouvant en être la cause. Il est peu probable que vous appeliez setLevel () dans une application Web et un code source autre que Restlet, donc cela ne semble pas être la raison.

Ensuite, afin de vérifier que la deuxième raison est correcte, j'ai décidé d'ajouter une instruction System.out.println () à cet initialiseur statique et de vérifier l'opération.

En d'autres termes, c'est ce que c'est.

ServiceEndpointApplication (la classe qui est le point de départ de l'appel Restlet d'une application Web)

     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");
     }

Cela vous dira si cette classe n'est pas chargée ou s'il y a des exceptions (erreurs) dans l'initialiseur statique pour le multithreading.

Cependant, le résultat de la sortie lorsque l'événement a été reproduit était le suivant.

ServiceEndpointApplication#clinit start
ServiceEndpointApplication#clinit end

En d'autres termes, il est certain qu'il est réglé sur «Level.OFF». Ni la première ni la deuxième raison ne semblent être correctes.

Vous utilisez un chargeur de classe différent?

Si tel est le cas, Restlet n'utilise peut-être pas une instance de journalisation (avec un niveau de journal non valide) pré-générée par l'application Web, par exemple parce qu'elle a été initialisée par un chargeur de classe différent.

J'ai donc fait les corrections suivantes et essayé de confirmer à nouveau la reproduction. Le nom et l'ID de l'instance de journalisation et les informations du chargeur de classe chargé sont sortis à l'endroit où l'instance de journalisation est générée pour la première fois et à l'endroit où elle est acquise et sortie dans le journal.

ServiceEndpointApplication (la classe qui est le point de départ de l'appel Restlet d'une application Web)

     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));
	}
}

La sortie ressemble à ceci:

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

Le résultat montre que les classes de journalisation sont chargées à partir du même chargeur de classe mais sont des instances différentes. Cela peut signifier que l'instance de journalisation une fois créée a été détruite et nouvellement créée.

D'autres possibilités?

Donc, au lieu du début, Javadoc de java.util.logging.Logger.getLogger () J'ai décidé de vérifier .html # getLogger-java.lang.String-). Et j'ai trouvé la description suivante.

Remarque: LogManager ne peut contenir que des références faibles aux enregistreurs nouvellement créés. Il est important de comprendre qu'un enregistreur précédemment créé avec le nom spécifié peut être récupéré à tout moment en l'absence d'une référence forte à l'enregistreur. En particulier, il s'agit de deux appels consécutifs, tels que getLogger ("MyLogger"). Log (...) et "MyLogger" s'il n'y a aucune référence forte à un enregistreur nommé "MyLogger" n'importe où dans le programme. Cela signifie qu'un autre objet de journalisation nommé peut être utilisé.

En d'autres termes, si un GC se produit dans un court laps de temps (même 1 milliseconde) entre l'appel de l'initialiseur statique ServiceEndpointApplication et l'appel de LogFilter # afterHandle (), alorsLogger.getLogger ()Peut être une autre instance, et le niveau de journalisation que vous auriez dû définir sera la valeur par défaut.

Si GC ne se produit pas dans ce court laps de temps, l'instance de journalisation sera conservée (= fortement référencée) dans la classe Restlet après cela, donc elle ne sera pas soumise à GC pour toujours (à moins qu'elle ne soit redémarrée). .. C'est pourquoi les nombreux redémarrages n'ont causé l'événement qu'une seule fois.

Vérifiez le fonctionnement

Si vous essayez de reproduire cette opération avec un programme simple, ce sera comme suit.

	public static void main(String[] args) {
		Logger.getLogger("test").setLevel(Level.OFF);
		//Si GC se produit ici,
		System.gc();
		//Après cela, getLevel()Renvoie null.
		System.out.println(Logger.getLogger("test").getLevel());
	}

Le résultat sera «nul». Si vous mettez en commentaire System.gc (); et qu'aucun GC ne se produit entre-temps, ʻOFF` est affiché.

Je vois souvent du code qui définit un enregistreur sur une variable de champ comme celle ci-dessous, pour une raison (empêchant GC de perdre les attributs que vous avez définis pour une instance):

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

Modifions donc le code source. Serait-ce comme suit si seule la correction minimale était apportée?

ServiceEndpointApplication (la classe qui est le point de départ de l'appel Restlet d'une application Web)

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

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

En fait, après avoir appliqué ce correctif, j'ai essayé de vérifier l'opération 20 fois avec la procédure de reproduction que j'ai trouvée, mais cet événement ne s'est pas produit. Comme le taux de rappel était d'environ une fois toutes les 5 fois, on peut dire qu'il n'y a pas de problème s'il ne se reproduit pas même s'il est fait 20 fois ($ \ scriptsize {(1 --0.8 ^ {20}) * 100 ≒ 99 \ %} $ Je suis sûr).

finalement

Je répondrai à nouveau à la première question.

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

Ce code n'a aucune garantie de supprimer la sortie du journal pour un enregistreur nommé test. En d'autres termes, les chances que la prochaine méthode ʻinfo () imprime test! `Sont non nulles.

    Logger.getLogger("test").setLevel(Level.OFF);
    //Si GC se produit ici, Logger.getLogger()Renvoie une autre instance
    Logger.getLogger("test").info("test!");

[^ 1]: Pour être exact, cela dépend du format de sortie du journal d'accès Tomcat. Dans cet environnement, c'était le format de sortie par défaut. [^ 2]: Restlet est un framework OSS pour la création d'applications Web RESTfull. [^ 3]: Ce commit a été corrigé. Comment y remédier n'est pas bon, mais ...