Un fonctionnalité pratique du framework de logging Apache Log4J est le NDC (pour Nested Diagnostic Contexts). Ce dernier permet de tracer et suivre plusieurs instances d’un même traitement dans un seul fichier de log. Une utilisation typique est le fichier de log d’une application web s’exécutant sur un serveur d’applications, car plusieurs instances d’une même servlet (et de plusieurs servlets) s’exécutent en même temps pour servir les utilisateurs.
La fonctionnalité permet donc de mieux comprendre le déroulement d’un traitement, en particulier lors qu’un problème survient lors d’un tir de charges ou sur un environnement en production. Et imaginons que ce problème ‘ne se reproduit pas’ en environnement de recette / développement, et donc l’origine pourrait être ces accès multiples en même temps…
Un développeur seul sur sa machine génère que un seul log séquentiel, mais avec de multiples utilisateurs, le log devient un enchevêtrement de plusieurs traitements séquentiels.
Voici un exemple de log applicatif pendant un tir de charges :
[2008-01-15 20:31:50,750][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:31:50,755][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok => org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@1ba287e [2008-01-15 20:31:50,757][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list [2008-01-15 20:31:50,758][DEBUG] (JndiJdbcTableView.java:62) - doGet() - Mise en attribut resultat [2008-01-15 20:31:50,758][DEBUG] (JndiJdbcTableView.java:64) - doGet() - Renvoi vers JSP [2008-01-15 20:31:50,759][DEBUG] (JndiJdbcTableView.java:78) - doGet() - end [2008-01-15 20:31:50,768][DEBUG] (JndiJdbcWithValidationTableView.java:48) - doGet() - start [2008-01-15 20:31:50,769][INFO ] (JndiJdbcWithValidationTableView.java:56) - doGet() - Ok connexion [2008-01-15 20:31:50,769][DEBUG] (JndiJdbcWithValidationTableView.java:60) - doGet() - Appel Boxers => bdSelectAll [2008-01-15 20:31:50,770][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:31:50,775][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok => org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@1d2f8be [2008-01-15 20:31:50,776][INFO ] (DirectJdbcTableView.java:60) - doGet() - Ok connexion [2008-01-15 20:31:50,777][DEBUG] (DirectJdbcTableView.java:64) - doGet() - Appel Boxers => bdSelectAll [2008-01-15 20:31:50,777][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:31:50,775][INFO ] (DirectJdbcTableView.java:60) - doGet() - Ok connexion [2008-01-15 20:31:50,778][DEBUG] (DirectJdbcTableView.java:64) - doGet() - Appel Boxers => bdSelectAll [2008-01-15 20:31:50,778][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:31:50,780][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list [2008-01-15 20:31:50,780][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet() - Mise en attribut resultat [2008-01-15 20:31:50,780][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet() - Renvoi vers JSP [2008-01-15 20:31:50,783][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet() - end [2008-01-15 20:31:50,784][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok => com.mysql.jdbc.ResultSet@10de02d [2008-01-15 20:31:50,786][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list [2008-01-15 20:31:50,786][DEBUG] (DirectJdbcTableView.java:66) - doGet() - Mise en attribut resultat [2008-01-15 20:31:50,787][DEBUG] (DirectJdbcTableView.java:68) - doGet() - Renvoi vers JSP [2008-01-15 20:31:50,788][DEBUG] (DirectJdbcTableView.java:85) - doGet() - end [2008-01-15 20:31:50,789][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok => com.mysql.jdbc.ResultSet@172c403 [2008-01-15 20:31:50,786][INFO ] (DirectJdbcTableView.java:60) - doGet() - Ok connexion [2008-01-15 20:31:50,791][DEBUG] (DirectJdbcTableView.java:64) - doGet() - Appel Boxers => bdSelectAll [2008-01-15 20:31:50,791][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:31:50,792][DEBUG] (JndiJdbcWithValidationTableView.java:48) - doGet() - start [2008-01-15 20:31:50,792][INFO ] (JndiJdbcWithValidationTableView.java:56) - doGet() - Ok connexion [2008-01-15 20:31:50,793][DEBUG] (JndiJdbcWithValidationTableView.java:60) - doGet() - Appel Boxers => bdSelectAll [2008-01-15 20:31:50,793][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:31:50,794][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list [2008-01-15 20:31:50,794][DEBUG] (DirectJdbcTableView.java:66) - doGet() - Mise en attribut resultat [2008-01-15 20:31:50,795][DEBUG] (DirectJdbcTableView.java:68) - doGet() - Renvoi vers JSP [2008-01-15 20:31:50,796][DEBUG] (DirectJdbcTableView.java:85) - doGet() - end [2008-01-15 20:31:50,798][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok => org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@695586 [2008-01-15 20:31:50,799][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list
La fonctionnalité NDC ajoute la possibilité d’avoir un « identifiant » de traitement, par exemple le nombre de secondes depuis le 1er janvier 1970. Ainsi le log devient un enchevêtrement de traitements séquentiels identifiés.
Et voici un exemple de log applicatif avec NDC :
[2008-01-15 20:07:55,920][DEBUG] (DaoBoxers.java:27) - bdSelectAll(1200427675911) - ResultSet ok => org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@19e907 [2008-01-15 20:07:55,921][DEBUG] (DaoBoxers.java:36) - bdSelectAll(1200427675911) - Retour list [2008-01-15 20:07:55,922][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet(1200427675911) - Mise en attribut resultat [2008-01-15 20:07:55,922][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet(1200427675911) - Renvoi vers JSP [2008-01-15 20:07:55,924][DEBUG] (DaoBoxers.java:27) - bdSelectAll(1200427675917) - ResultSet ok => org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@93a96c [2008-01-15 20:07:55,925][DEBUG] (DaoBoxers.java:36) - bdSelectAll(1200427675917) - Retour list [2008-01-15 20:07:55,926][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet(1200427675917) - Mise en attribut resultat [2008-01-15 20:07:55,926][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet(1200427675917) - Renvoi vers JSP [2008-01-15 20:07:55,927][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet(1200427675911) - end [2008-01-15 20:07:55,929][DEBUG] (DirectJdbcTableView.java:49) - doGet(1200427675929) - start [2008-01-15 20:07:55,931][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet(1200427675917) - end [2008-01-15 20:07:55,934][DEBUG] (DirectJdbcInInitTableView.java:49) - doGet(1200427675934) - start [2008-01-15 20:07:55,938][DEBUG] (JndiJdbcWithValidationTableView.java:48) - doGet(1200427675938) - start [2008-01-15 20:07:55,938][INFO ] (JndiJdbcWithValidationTableView.java:56) - doGet(1200427675938) - Ok connexion [2008-01-15 20:07:55,939][DEBUG] (JndiJdbcWithValidationTableView.java:60) - doGet(1200427675938) - Appel Boxers => bdSelectAll [2008-01-15 20:07:55,941][DEBUG] (net.milamberspace.dao.DaoBoxers.java:24) - bdSelectAll(1200427675938) - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:07:55,941][INFO ] (DirectJdbcTableView.java:60) - doGet(1200427675929) - Ok connexion [2008-01-15 20:07:55,942][DEBUG] (DirectJdbcTableView.java:64) - doGet(1200427675929) - Appel Boxers => bdSelectAll [2008-01-15 20:07:55,942][DEBUG] (DaoBoxers.java:24) - bdSelectAll(1200427675929) - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:07:55,947][DEBUG] (DaoBoxers.java:27) - bdSelectAll(1200427675938) - ResultSet ok => org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@17dde01 [2008-01-15 20:07:55,948][DEBUG] (DaoBoxers.java:36) - bdSelectAll(1200427675938) - Retour list [2008-01-15 20:07:55,949][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet(1200427675938) - Mise en attribut resultat [2008-01-15 20:07:55,949][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet(1200427675938) - Renvoi vers JSP [2008-01-15 20:07:55,950][DEBUG] (DaoBoxers.java:27) - bdSelectAll(1200427675929) - ResultSet ok => com.mysql.jdbc.ResultSet@7a3c6c [2008-01-15 20:07:55,952][DEBUG] (DaoBoxers.java:36) - bdSelectAll(1200427675929) - Retour list [2008-01-15 20:07:55,952][DEBUG] (DirectJdbcTableView.java:66) - doGet(1200427675929) - Mise en attribut resultat [2008-01-15 20:07:55,952][DEBUG] (DirectJdbcTableView.java:68) - doGet(1200427675929) - Renvoi vers JSP [2008-01-15 20:07:55,954][DEBUG] (DirectJdbcTableView.java:85) - doGet(1200427675929) - end [2008-01-15 20:07:55,956][INFO ] (DirectJdbcInInitTableView.java:57) - doGet(1200427675934) - Ok connexion [2008-01-15 20:07:55,956][DEBUG] (DirectJdbcInInitTableView.java:61) - doGet(1200427675934) - Appel Boxers => bdSelectAll [2008-01-15 20:07:55,957][DEBUG] (DaoBoxers.java:24) - bdSelectAll(1200427675934) - SQL => SELECT ID, PRENOM, NOM FROM BOXERS [2008-01-15 20:07:55,958][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet(1200427675938) - end [2008-01-15 20:07:55,961][DEBUG] (DaoBoxers.java:27) - bdSelectAll(1200427675934) - ResultSet ok => com.mysql.jdbc.ResultSet@283198 [2008-01-15 20:07:55,963][DEBUG] (DaoBoxers.java:36) - bdSelectAll(1200427675934) - Retour list
Cela permet une lecture plus facile des logs (la couleur n’est pas incluse ;-)), dès lors que l’on sait utiliser la commande grep sous Unix en faisant quelques petits grep sur l’identifiant. (par exemple : grep 1200426850018 mon_log.txt)
Comme faire pour utiliser NDC ? Et bien tout d’abord dans le fichier de configuration de Log4J, le fameux log4j.properties. Il faut ajouter la balise « %x » dans le ConversionPattern, celle-ci sera remplacée par l’identifiant unique défini lors de l’utilisation de NDC.
Exemple de fichier log4j.properties
log4j.rootLogger=DEBUG, LOG1 log4j.appender.LOG1=org.apache.log4j.ConsoleAppender log4j.appender.LOG1.layout=org.apache.log4j.PatternLayout log4j.appender.LOG1.layout.ConversionPattern=[%d][%-5p] (%C.java:%L) - %M(%x) - %m%n
Au niveau du code source Java, on utilisera deux méthodes de la classe statique NDC.
- NDC.push(String ID) qui permet de poser un identifiant
- NDC.pop() qui permet de dépiler le dernier identifiant posé
Voici un exemple simple d’utilisation pour une servlet, avec ici, l’utilisation de « new Date().getTime() » comme identifiant :
protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
NDC.push(String.valueOf(new Date().getTime()));
logger.debug("start");
Connection connection = null;
try {
connection = getDataSource().getConnection();
logger.info("Ok connexion");
DaoBoxers dao = new DaoBoxers();
dao.setConnection(connection);
ArrayList list = dao.bdSelectAll();
request.setAttribute("beanListeBoxer", list);
this.getServletContext().getRequestDispatcher("/tableview.jsp").forward(request, response);
} catch (Exception e) {
logger.error(e);
throw new ServletException(e.getMessage());
} finally {
try {
connection.close();
} catch (SQLException sqle) {
logger.error(sqle);
}
logger.debug("end");
NDC.pop();
}
}
Bien entendu, les appels à logger.xxxx() dans les méthodes du DAO vont également bénéficier de l’identifiant NDC.
Espérons que ce billet vous sera utile.
La page de manuel de Log4J.