JOT Première partie : Contextualisation des logs avec log4j

Ce billet est le premier d’une série décrivant les principes et composants du « Java Operations Toolkit ». JOT est un projet encore embryonnaire (je le publierai bientôt sous license Open Source, et sous un autre nom, JOT étant déjà pris… Si certains parmi vous ont une idée…). Son objectif est d’offrir aux applications java un ensemble d’utilitaires, d’API et de bonne pratiques visant à en faciliter l’exploitation.

Comme son titre le suggère, ce premier billet concerne la journalisation, connue également sous son sobriquet anglo-saxon de « log ».
Depuis plusieurs années maintenant, l’utilisation d’un framework dédié pour gérer les logs s’est généralisée. Log4j a ouvert la voie, suivi par framework java.util.logging à partir du JDK 1.4, qui adopte une architecture très similaire à celle de log4j, tout en proposant une nomenclature moins intuitive (du moins pour ceux qui pensent que « DEBUG » désigne un niveau de journalisation plus évident que « FINEST »). Citons également les meta-frameworks Commons Logging et SLF4J, qui offrent une couche d’adaptation au dessus des différents frameworks pour en unifier l’usage.

L’objet ici n’est pas de comparer ces différentes solutions : elles sont toutes très proches et offrent toutes les fonctionnalités attendues d’un utilitaire de logging:

• une API simple et intuitive, style log.debug(message) ou log.info(message)
• une configuration externalisée permettant d’activer ou de désactiver certaines traces sans intervention sur les sources ou les binaires
• la possibilité de configurer des flux de sortie divers pour les messages (console, fichiers avec rotation, sockets, base de données, JMS, syslog, NTEventLog, etc.), avec une granularité très fine
• la possibilité de configurer le format des messages

On ne peut que se féliciter de l’adoption massive de ces frameworks, en particulier du plus illustre d’entre eux, log4j. Cette adoption a pourtant bien souvent un revers: disposer de ces fonctionnalités a exempté les architectes et développeurs d’une réflexion réelle sur l’usage des logs. La politique de journalisation se réduit fréquemment à cette simple directive : « Utiliser log4j », et le code est en conséquence saupoudré plus ou moins densément (selon l’humeur ou la sensibilité du développeur) d’instructions du style

Logger log = Logger.getLogger(this.getClass());

	[...]
	log.debug("Avant call gloubiboulga casimir.isHeureux()=" + casimir.isHeureux());
	casimir.gloubiboulga();
	log.debug("Après call gloubiboulga casimir.isHeureux()=" + casimir.isHeureux());
	[...]
	catch (Exception ex){
	    log.error("Une erreur s'est produite", ex);
	    throw new RealBadThingHappenedException(ex);
	}
	[...]

Plusieurs problèmes dans cette approche:

• le logger utilisé porte le nom de la classe. Il doit être configuré comme tel (y compris avec les mécanisme d’héritage). Les noms de classe (et de package) n’ont pas vraiment de sens pour les équipes d’exploitation, ce qui limite souvent leur autonomie sur la configuration des traces.
• les messages de debug manquent de consistance, et n’ont de véritable intérêt que pour le développeur au moment de la mise au point de la classe concernée (ce qui, notons-le, n’est pas critique; par nature, les messages de déboguage ne sont pas destinés aux exploitants).
• si plusieurs threads exécutent simultanément la méthode, les traces seront entrelacées et il sera difficile de rétablir le séquencement des opérations
• le message d’erreur est laconique et la pile d’appel, pour utile qu’elle soit, n’est interprétable que par l’ingénierie.
• il n’y a pas de trace intermédiaire entre DEBUG et ERROR, ce qui limite la capacité de diagnostic en exploitation
• l’utilisation des API de log tel quel peut poser des problèmes de performance (cf ce billet)

Nous nous pencherons aujourd’hui sur le problème de la corrélation: dans un environnement multithreadé et distribué, comment relier entre eux les messages relatifs à une même interaction?

Corréler les logs

Dans un environnement multi-threadé, et a fortiori dans un environnement distribué, il est difficile, sinon impossible, de corréler l’ensemble des traces issues d’un même traitement ou d’une même interaction (que l’on nommera désormais transaction pour plus de clareté). La solution proposée par log4j pour adresser ce problème consiste à placer dans chaque message un identifiant de corrélation unique pour chaque transaction. On trouvera une description de ce principe dans « Patterns for Logging Diagnostic Messages »(1).
Log4j supporte nativement cette contextualisation, aux travers des classes org.apache.log4j.NDC et org.apache.log4j.MDC (ce n’est pas le cas de java.util.logging; l’extension de java.util.logging pour supporter les NDC serait néanmoins très simple).
Pour implémenter ce mécanisme, il suffit donc d’intercepter le point d’entrée du système et de fixer l’identifiant de correlation dans le MDC (ou le NDC).
Le cas le plus simple est celui d’une application web, pour laquelle cette interception se fait au moyen d’un filtre:

public class Log4jMDCServletFilter implements Filter {
	public void doFilter(ServletRequest request, 
						 ServletResponse response, 
						 FilterChain chain) 
					throws IOException, ServletException {
		try {
			if (MDC.get("CorrelationID") == null)
				MDC.put("CorrelationID", JOTUtils.generateCorrelationID());
			chain.doFilter(request, response);
		}
		finally {
			MDC.remove("CorrelationID");
		}
	}

...
}

Il suffit ensuite d’utiliser le pattern (cf. org.apache.log4j.PatternLayout) suivant pour disposer systématiquement dans les messages d’un identifiant de correlation :
[code]
%d{ISO8601} [%t] %-5p %c %X{CorrelationID} – %m\n
[/code]

Il est bien sûr possible de fournir un contexte plus riche (par exemple le nom de l’utilisateur, le use case, le service, etc.), et ce mécanisme peut servir de base à un filtrage, permettant d’augmenter le niveau de trace uniquement pour un sous-ensemble de clients ou de contextes.
Le composant NDC (pour Nested Diagnostic Context) permet quant à lui de gérer une pile de contextes imbriqués.

Néanmoins, MDC et NDC s’appuie sur des variables ThreadLocal, limitées donc à l’espace mémoire de la JVM. Les choses se compliquent donc singulièrement lorsque les interactions sont distribuées et que l’on souhaite corréler les traces aux travers de plusieurs JVMs.

Dans un contexte distribué, l’identifiant de correlation doit être propagé aux différents composants traversés. Il n’existe malheureusement pas de moyen universel de réaliser cette propagation : elle dépend du protocole utilisé pour réaliser les invocations distantes. Le plus souvent, cependant, la distribution se fera au moyen de RMI/IIOP.
Le protocole IIOP bénéficie d’une technologie standard d’interception: les PortableInterceptors CORBA. Voici donc un moyen de réaliser la propagation transaparente de l’identifiant de corrélation sur IIOP.

Premier élément, un intercepteur client chargé d’enrichir le flux IIOP d’un contexte spécifique portant l’identifiant de corrélation:

...
public class CORBAClientInterceptor
	extends org.omg.CORBA.LocalObject
	implements ClientRequestInterceptor {
	
	private org.omg.PortableInterceptor.ORBInitInfo info;
	private int t_slot;

	private static final long serialVersionUID = -6768740178708556025L;

	public CORBAClientInterceptor(ORBInitInfo info, int t_slot) {
		this.info = info;
		this.t_slot = t_slot;
	}

	public String name() {
		return "JOT Log correlation id propagation - Client Interceptor";
	}

	public void send_request(ClientRequestInfo ri) throws ForwardRequest {
		org.omg.CORBA.Any any = null;
		try {
			any = ri.get_slot(t_slot);
		}
		catch (org.omg.PortableInterceptor.InvalidSlot is) {
			throw new org.omg.CORBA.INTERNAL("JOTClientInterceptor : Invalid slot : " + is.getMessage());		
		}
		
		if ( ( any.type().kind().value() == org.omg.CORBA.TCKind._tk_null ) ||
		     ( any.type().kind().value() == org.omg.CORBA.TCKind._tk_void ) )
			return;
		
		org.omg.IOP.ServiceContext serviceCtx = new org.omg.IOP.ServiceContext();
		serviceCtx.context_id = 995;
		try {
			serviceCtx.context_data = ((String)MDC.get("CorrelationID")).getBytes("UTF-8");
		} catch (UnsupportedEncodingException e) {
			throw new org.omg.CORBA.INTERNAL("JOTClientInterceptor : UTF-8 Not Supported : " + e.getMessage());
		}
		ri.add_request_service_context(serviceCtx, true);
	}
...
}

Il faut ensuite un intercepteur symétrique, côté serveur, chargé de décoder l’identifiant de corrélation et de le placer dans le NDC log4j:

...
public class CORBAServerInterceptor extends LocalObject implements
		ServerRequestInterceptor {

	private static final long serialVersionUID = -5574812890862607150L;
	
	private org.omg.PortableInterceptor.ORBInitInfo info;
	private int t_slot;

	public CORBAServerInterceptor(ORBInitInfo info, int t_slot) {
		this.info = info;
		this.t_slot = t_slot;
	}

	public String name() {
		return "JOT Log correlation id propagation - Server Interceptor";
	}

	public void receive_request_service_contexts(ServerRequestInfo ri)
			throws ForwardRequest {
		org.omg.IOP.ServiceContext serviceCtx = null;
		try
		{
			serviceCtx = ri.get_request_service_context(995);
		}
		catch (org.omg.CORBA.BAD_PARAM bp){
			//Le client n'a pas fourni de contexte, on en génère un
			MDC.put("CorrelationID", JOTUtils.generateTID());
			return;
		}
		
		try {
			MDC.put("CorrelationID", new String(serviceCtx.context_data, "UTF-8"));
		} catch (UnsupportedEncodingException e) {
			throw new org.omg.CORBA.INTERNAL("JOTServerInterceptor : UTF-8 Not Supported : " + e.getMessage());
		}
	}
...
}

Et voici la classe d’initialisation qui permet d’enregistrer les intercepteurs:

...
public class CORBAInitializer extends org.omg.CORBA.LocalObject implements
		ORBInitializer {

	/**
	 * Log correlation slot id
	 */
	private int t_slot;

	/**
	 * Pre initialization
	 */
	public void pre_init(org.omg.PortableInterceptor.ORBInitInfo info) {
		t_slot = info.allocate_slot_id();

		CORBAClientInterceptor clientInterceptor = new CORBAClientInterceptor(
				info, t_slot);
		try {
			info.add_client_request_interceptor(clientInterceptor);
			// info.add_server_request_interceptor(serverInterceptor);
		} catch (org.omg.PortableInterceptor.ORBInitInfoPackage.DuplicateName dn) {
			String msg = "Error in initializer: Duplicate name when adding the interceptor : "
					+ dn.getMessage();
			throw new org.omg.CORBA.INTERNAL(msg);
		}
	}

	public void post_init(ORBInitInfo info) {
	}

}

L’implémentation de ce mécanisme pour d’autres protocoles dépend bien sût des capacités de ce protocole. Si le protocole est HTTP, il est assez simple d’ajouter les entêtes adéquates dans les requêtes. Pour d’autres protocoles, les choses peuvent s’avérer plus difficile, voire impossible pour des protocoles propriétaires.

Dans le prochain billet, nous chercherons à centraliser la configuration des catégories et à en simplifier l’usage.

Références
(1) « Patterns for Logging Diagnostic Messages » dans « Pattern Languages of Program Design 3 », édité par R. Martin, D. Riehle, et F. Buschmann (Addison-Wesley, 1997).