{"id":58,"date":"2008-01-15T20:46:38","date_gmt":"2008-01-15T20:46:38","guid":{"rendered":"http:\/\/blog.milamberspace.net\/index.php\/2008\/01\/15\/utilisation-de-ndc-de-apache-log4j-pour-tracer-et-suivre-lexecution-dune-application-java-58.html"},"modified":"2008-01-15T21:07:31","modified_gmt":"2008-01-15T21:07:31","slug":"utilisation-de-ndc-de-apache-log4j-pour-tracer-et-suivre-lexecution-dune-application-java","status":"publish","type":"post","link":"https:\/\/blog.milamberspace.net\/index.php\/2008\/01\/15\/utilisation-de-ndc-de-apache-log4j-pour-tracer-et-suivre-lexecution-dune-application-java-58.html","title":{"rendered":"Utilisation de NDC de Apache Log4J pour tracer et suivre l&rsquo;ex\u00e9cution d&rsquo;une application Java"},"content":{"rendered":"<p>Un fonctionnalit\u00e9 pratique du framework de logging Apache Log4J est le NDC (<em>pour  Nested Diagnostic Contexts<\/em>). Ce dernier permet de tracer et suivre plusieurs instances d&rsquo;un m\u00eame traitement dans un seul fichier de log. Une utilisation typique est le fichier de log d&rsquo;une application web s&rsquo;ex\u00e9cutant sur un serveur d&rsquo;applications, car plusieurs instances d&rsquo;une m\u00eame servlet (et de plusieurs servlets) s&rsquo;ex\u00e9cutent en m\u00eame temps pour servir les utilisateurs.<\/p>\n<p>La fonctionnalit\u00e9 permet donc de mieux comprendre le d\u00e9roulement d&rsquo;un traitement, en particulier lors qu&rsquo;un probl\u00e8me survient lors d&rsquo;un tir de charges ou sur un environnement en production. Et imaginons que ce probl\u00e8me &lsquo;ne se reproduit pas&rsquo; en environnement de recette \/ d\u00e9veloppement, et donc l&rsquo;origine pourrait \u00eatre ces acc\u00e8s multiples en m\u00eame temps&#8230;<!--more--><\/p>\n<p>Un d\u00e9veloppeur seul sur sa machine g\u00e9n\u00e8re que un seul log s\u00e9quentiel, mais avec de multiples utilisateurs, le log devient un enchev\u00eatrement de plusieurs traitements s\u00e9quentiels.<\/p>\n<p><u>Voici un exemple de log applicatif pendant un tir de charges :<\/u><\/p>\n<pre>[2008-01-15 20:31:50,750][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:31:50,755][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok =&gt; org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@1ba287e\r\n[2008-01-15 20:31:50,757][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list\r\n[2008-01-15 20:31:50,758][DEBUG] (JndiJdbcTableView.java:62) - doGet() - Mise en attribut resultat\r\n[2008-01-15 20:31:50,758][DEBUG] (JndiJdbcTableView.java:64) - doGet() - Renvoi vers JSP\r\n[2008-01-15 20:31:50,759][DEBUG] (JndiJdbcTableView.java:78) - doGet() - end\r\n[2008-01-15 20:31:50,768][DEBUG] (JndiJdbcWithValidationTableView.java:48) - doGet() - start\r\n[2008-01-15 20:31:50,769][INFO ] (JndiJdbcWithValidationTableView.java:56) - doGet() - Ok connexion\r\n[2008-01-15 20:31:50,769][DEBUG] (JndiJdbcWithValidationTableView.java:60) - doGet() - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:31:50,770][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:31:50,775][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok =&gt; org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@1d2f8be\r\n[2008-01-15 20:31:50,776][INFO ] (DirectJdbcTableView.java:60) - doGet() - Ok connexion\r\n[2008-01-15 20:31:50,777][DEBUG] (DirectJdbcTableView.java:64) - doGet() - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:31:50,777][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:31:50,775][INFO ] (DirectJdbcTableView.java:60) - doGet() - Ok connexion\r\n[2008-01-15 20:31:50,778][DEBUG] (DirectJdbcTableView.java:64) - doGet() - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:31:50,778][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:31:50,780][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list\r\n[2008-01-15 20:31:50,780][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet() - Mise en attribut resultat\r\n[2008-01-15 20:31:50,780][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet() - Renvoi vers JSP\r\n[2008-01-15 20:31:50,783][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet() - end\r\n[2008-01-15 20:31:50,784][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok =&gt; com.mysql.jdbc.ResultSet@10de02d\r\n[2008-01-15 20:31:50,786][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list\r\n[2008-01-15 20:31:50,786][DEBUG] (DirectJdbcTableView.java:66) - doGet() - Mise en attribut resultat\r\n[2008-01-15 20:31:50,787][DEBUG] (DirectJdbcTableView.java:68) - doGet() - Renvoi vers JSP\r\n[2008-01-15 20:31:50,788][DEBUG] (DirectJdbcTableView.java:85) - doGet() - end\r\n[2008-01-15 20:31:50,789][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok =&gt; com.mysql.jdbc.ResultSet@172c403\r\n[2008-01-15 20:31:50,786][INFO ] (DirectJdbcTableView.java:60) - doGet() - Ok connexion\r\n[2008-01-15 20:31:50,791][DEBUG] (DirectJdbcTableView.java:64) - doGet() - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:31:50,791][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:31:50,792][DEBUG] (JndiJdbcWithValidationTableView.java:48) - doGet() - start\r\n[2008-01-15 20:31:50,792][INFO ] (JndiJdbcWithValidationTableView.java:56) - doGet() - Ok connexion\r\n[2008-01-15 20:31:50,793][DEBUG] (JndiJdbcWithValidationTableView.java:60) - doGet() - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:31:50,793][DEBUG] (DaoBoxers.java:24) - bdSelectAll() - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:31:50,794][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list\r\n[2008-01-15 20:31:50,794][DEBUG] (DirectJdbcTableView.java:66) - doGet() - Mise en attribut resultat\r\n[2008-01-15 20:31:50,795][DEBUG] (DirectJdbcTableView.java:68) - doGet() - Renvoi vers JSP\r\n[2008-01-15 20:31:50,796][DEBUG] (DirectJdbcTableView.java:85) - doGet() - end\r\n[2008-01-15 20:31:50,798][DEBUG] (DaoBoxers.java:27) - bdSelectAll() - ResultSet ok =&gt; org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@695586\r\n[2008-01-15 20:31:50,799][DEBUG] (DaoBoxers.java:36) - bdSelectAll() - Retour list<\/pre>\n<p>La fonctionnalit\u00e9 NDC ajoute la possibilit\u00e9 d&rsquo;avoir un \u00ab identifiant \u00bb de traitement, par exemple le nombre de secondes depuis le 1er janvier 1970. Ainsi le log devient un enchev\u00eatrement de traitements s\u00e9quentiels identifi\u00e9s.<br \/>\n<u> Et voici un exemple de log applicatif avec NDC :<\/u><\/p>\n<pre>[2008-01-15 20:07:55,920][DEBUG] (DaoBoxers.java:27) - bdSelectAll(<font color=\"#339966\">1200427675911<\/font>) - ResultSet ok =&gt; org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@19e907\r\n[2008-01-15 20:07:55,921][DEBUG] (DaoBoxers.java:36) - bdSelectAll(<font color=\"#339966\">1200427675911<\/font>) - Retour list\r\n[2008-01-15 20:07:55,922][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet(<font color=\"#339966\">1200427675911<\/font>) - Mise en attribut resultat\r\n[2008-01-15 20:07:55,922][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet(<font color=\"#339966\">1200427675911<\/font>) - Renvoi vers JSP\r\n[2008-01-15 20:07:55,924][DEBUG] (DaoBoxers.java:27) - bdSelectAll(<font color=\"#ff6600\">1200427675917<\/font>) - ResultSet ok =&gt; org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@93a96c\r\n[2008-01-15 20:07:55,925][DEBUG] (DaoBoxers.java:36) - bdSelectAll(<font color=\"#ff6600\">1200427675917<\/font>) - Retour list\r\n[2008-01-15 20:07:55,926][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet(<font color=\"#ff6600\">1200427675917<\/font>) - Mise en attribut resultat\r\n[2008-01-15 20:07:55,926][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet(<font color=\"#ff6600\">1200427675917<\/font>) - Renvoi vers JSP\r\n[2008-01-15 20:07:55,927][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet(<font color=\"#339966\">1200427675911<\/font>) - end\r\n[2008-01-15 20:07:55,929][DEBUG] (DirectJdbcTableView.java:49) - doGet(<font color=\"#0000ff\">1200427675929<\/font>) - start\r\n[2008-01-15 20:07:55,931][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet(<font color=\"#ff6600\">1200427675917<\/font>) - end\r\n[2008-01-15 20:07:55,934][DEBUG] (DirectJdbcInInitTableView.java:49) - doGet(<font color=\"#ff00ff\">1200427675934<\/font>) - start\r\n[2008-01-15 20:07:55,938][DEBUG] (JndiJdbcWithValidationTableView.java:48) - doGet(<font color=\"#ff0000\">1200427675938<\/font>) - start\r\n[2008-01-15 20:07:55,938][INFO ] (JndiJdbcWithValidationTableView.java:56) - doGet(<font color=\"#ff0000\">1200427675938<\/font>) - Ok connexion\r\n[2008-01-15 20:07:55,939][DEBUG] (JndiJdbcWithValidationTableView.java:60) - doGet(<font color=\"#ff0000\">1200427675938<\/font>) - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:07:55,941][DEBUG] (net.milamberspace.dao.DaoBoxers.java:24) - bdSelectAll(<font color=\"#ff0000\">1200427675938<\/font>) - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:07:55,941][INFO ] (DirectJdbcTableView.java:60) - doGet(<font color=\"#0000ff\">1200427675929<\/font>) - Ok connexion\r\n[2008-01-15 20:07:55,942][DEBUG] (DirectJdbcTableView.java:64) - doGet(<font color=\"#0000ff\">1200427675929<\/font>) - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:07:55,942][DEBUG] (DaoBoxers.java:24) - bdSelectAll(<font color=\"#0000ff\">1200427675929<\/font>) - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:07:55,947][DEBUG] (DaoBoxers.java:27) - bdSelectAll(<font color=\"#ff0000\">1200427675938<\/font>) - ResultSet ok =&gt; org.apache.tomcat.dbcp.dbcp.DelegatingResultSet@17dde01\r\n[2008-01-15 20:07:55,948][DEBUG] (DaoBoxers.java:36) - bdSelectAll(<font color=\"#ff0000\">1200427675938<\/font>) - Retour list\r\n[2008-01-15 20:07:55,949][DEBUG] (JndiJdbcWithValidationTableView.java:62) - doGet(<font color=\"#ff0000\">1200427675938<\/font>) - Mise en attribut resultat\r\n[2008-01-15 20:07:55,949][DEBUG] (JndiJdbcWithValidationTableView.java:64) - doGet(<font color=\"#ff0000\">1200427675938<\/font>) - Renvoi vers JSP\r\n[2008-01-15 20:07:55,950][DEBUG] (DaoBoxers.java:27) - bdSelectAll(<font color=\"#0000ff\">1200427675929<\/font>) - ResultSet ok =&gt; com.mysql.jdbc.ResultSet@7a3c6c\r\n[2008-01-15 20:07:55,952][DEBUG] (DaoBoxers.java:36) - bdSelectAll(<font color=\"#0000ff\">1200427675929<\/font>) - Retour list\r\n[2008-01-15 20:07:55,952][DEBUG] (DirectJdbcTableView.java:66) - doGet(<font color=\"#0000ff\">1200427675929<\/font>) - Mise en attribut resultat\r\n[2008-01-15 20:07:55,952][DEBUG] (DirectJdbcTableView.java:68) - doGet(<font color=\"#0000ff\">1200427675929<\/font>) - Renvoi vers JSP\r\n[2008-01-15 20:07:55,954][DEBUG] (DirectJdbcTableView.java:85) - doGet(<font color=\"#0000ff\">1200427675929<\/font>) - end\r\n[2008-01-15 20:07:55,956][INFO ] (DirectJdbcInInitTableView.java:57) - doGet(<font color=\"#ff00ff\">1200427675934<\/font>) - Ok connexion\r\n[2008-01-15 20:07:55,956][DEBUG] (DirectJdbcInInitTableView.java:61) - doGet(<font color=\"#ff00ff\">1200427675934<\/font>) - Appel Boxers =&gt; bdSelectAll\r\n[2008-01-15 20:07:55,957][DEBUG] (DaoBoxers.java:24) - bdSelectAll(<font color=\"#ff00ff\">1200427675934<\/font>) - SQL =&gt; SELECT ID, PRENOM, NOM FROM BOXERS\r\n[2008-01-15 20:07:55,958][DEBUG] (JndiJdbcWithValidationTableView.java:78) - doGet(<font color=\"#ff0000\">1200427675938<\/font>) - end\r\n[2008-01-15 20:07:55,961][DEBUG] (DaoBoxers.java:27) - bdSelectAll(<font color=\"#ff00ff\">1200427675934<\/font>) - ResultSet ok =&gt; com.mysql.jdbc.ResultSet@283198\r\n[2008-01-15 20:07:55,963][DEBUG] (DaoBoxers.java:36) - bdSelectAll(<font color=\"#ff00ff\">1200427675934<\/font>) - Retour list<\/pre>\n<p>Cela permet une lecture plus facile des logs (la couleur n&rsquo;est pas incluse ;-)), d\u00e8s lors que l&rsquo;on sait utiliser la commande grep sous Unix en faisant quelques petits grep sur l&rsquo;identifiant. (par exemple : grep 1200426850018 mon_log.txt)<\/p>\n<p>Comme faire pour utiliser NDC ? Et bien tout d&rsquo;abord dans le fichier de configuration de Log4J, le fameux log4j.properties. Il faut ajouter la balise \u00ab %x \u00bb dans le ConversionPattern, celle-ci sera remplac\u00e9e par l&rsquo;identifiant unique d\u00e9fini lors de l&rsquo;utilisation de NDC.<\/p>\n<p><u>Exemple de fichier log4j.properties<\/u><\/p>\n<pre><font color=\"#800000\">log4j.rootLogger=DEBUG, LOG1\r\nlog4j.appender.LOG1=org.apache.log4j.ConsoleAppender\r\nlog4j.appender.LOG1.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.LOG1.layout.ConversionPattern=[%d][%-5p] (%C.java:%L) - %M(<strong>%x<\/strong>) - %m%n<\/font><\/pre>\n<p>Au niveau du code source Java, on utilisera deux m\u00e9thodes de la classe statique NDC.<\/p>\n<ul>\n<li><em>NDC.push(String ID)<\/em> qui permet de poser un identifiant<\/li>\n<li><em>NDC.pop()<\/em> qui permet de d\u00e9piler le dernier identifiant pos\u00e9<\/li>\n<\/ul>\n<p>Voici un exemple simple d&rsquo;utilisation pour une servlet, avec ici, l&rsquo;utilisation de \u00ab new Date().getTime() \u00bb comme identifiant :<\/p>\n<pre>protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {\r\n NDC.push(String.valueOf(new Date().getTime()));\r\n logger.debug(\"start\");\r\n Connection connection = null;\r\n try {\r\n \tconnection = getDataSource().getConnection();\r\n \tlogger.info(\"Ok connexion\");\r\n\tDaoBoxers dao = new DaoBoxers();\r\n \tdao.setConnection(connection);\r\n \tArrayList<boxer> list = dao.bdSelectAll();\r\n \trequest.setAttribute(\"beanListeBoxer\", list);\r\n \tthis.getServletContext().getRequestDispatcher(\"\/tableview.jsp\").forward(request, response);\r\n<\/boxer> } catch (Exception e) {\r\n \tlogger.error(e);\r\n \tthrow new ServletException(e.getMessage());\r\n } finally {\r\n \ttry {\r\n \t\tconnection.close();\r\n \t} catch (SQLException sqle) {\r\n \t\tlogger.error(sqle);\r\n \t}\r\n \tlogger.debug(\"end\");\r\n \tNDC.pop();\r\n }\r\n}<\/pre>\n<p>Bien entendu, les appels \u00e0 logger.xxxx() dans les m\u00e9thodes du DAO vont \u00e9galement b\u00e9n\u00e9ficier de l&rsquo;identifiant NDC.<\/p>\n<p>Esp\u00e9rons que ce billet vous sera utile.<\/p>\n<p><em>La page de<a href=\"http:\/\/logging.apache.org\/log4j\/1.2\/manual.html\" target=\"_blank\"> manuel de Log4J<\/a>.<\/em><\/p>\n","protected":false},"excerpt":{"rendered":"<p>Un fonctionnalit\u00e9 pratique du framework de logging Apache Log4J est le NDC (pour Nested Diagnostic Contexts). Ce dernier permet de tracer et suivre plusieurs instances d&rsquo;un m\u00eame traitement dans un seul fichier de log. Une utilisation typique est le fichier de log d&rsquo;une application web s&rsquo;ex\u00e9cutant sur un serveur d&rsquo;applications, car plusieurs instances d&rsquo;une m\u00eame &hellip; <a href=\"https:\/\/blog.milamberspace.net\/index.php\/2008\/01\/15\/utilisation-de-ndc-de-apache-log4j-pour-tracer-et-suivre-lexecution-dune-application-java-58.html\" class=\"more-link\">Continuer la lecture de <span class=\"screen-reader-text\">Utilisation de NDC de Apache Log4J pour tracer et suivre l&rsquo;ex\u00e9cution d&rsquo;une application Java<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[32,12,42,17,41,62,57],"tags":[329,324,340,63],"class_list":["post-58","post","type-post","status-publish","format-standard","hentry","category-apache","category-developpement","category-j2ee","category-java","category-jee","category-log4j","category-supervision","tag-apache","tag-java","tag-log4j","tag-ndc"],"_links":{"self":[{"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/posts\/58","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/comments?post=58"}],"version-history":[{"count":0,"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/posts\/58\/revisions"}],"wp:attachment":[{"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/media?parent=58"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/categories?post=58"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.milamberspace.net\/index.php\/wp-json\/wp\/v2\/tags?post=58"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}