{"id":1077,"date":"2016-09-01T11:59:18","date_gmt":"2016-09-01T11:59:18","guid":{"rendered":"http:\/\/blog.paranoidprofessor.com\/?p=1077"},"modified":"2016-09-02T19:12:13","modified_gmt":"2016-09-02T19:12:13","slug":"better-logging-than-printf-using-log4j-part-ii","status":"publish","type":"post","link":"https:\/\/blog.paranoidprofessor.com\/index.php\/2016\/09\/01\/better-logging-than-printf-using-log4j-part-ii\/","title":{"rendered":"better logging than printf &#8211; using log4j &#8211; part II"},"content":{"rendered":"<p>However, Just like with computers, cars and women there is always a faster, bigger, or better model on the horizon.<\/p>\n<p>Version 1.2 of log4j has reached its end of life on August 5th 2015 but there is a version 2 to take it place. \u00a0There is a lot of things to like about the new version of log4j with some of the benefits being.<\/p>\n<ul>\n<li>Improved performance<\/li>\n<li>Support for multiple API&#8217;s<\/li>\n<li>Plugin architecture<\/li>\n<li>Java 8 lambda support<\/li>\n<li>Custom log levels<\/li>\n<\/ul>\n<p>Some of the basics of log4j was explained in <a href=\"http:\/\/blog.paranoidprofessor.com\/index.php\/2016\/08\/29\/better-logging-than-printf-using-log4j-part-i\/\">part I.<\/a><\/p>\n<h2>Log4j version 1.2<\/h2>\n<p>Using version 1.2 of log4j it is really easy to send our output to either the screen or to a file.<\/p>\n<h3>Property file<\/h3>\n<div class=\"sbody-code\">\n<pre><code>log4j.rootLogger=INFO, stdout, pgmlogfile\r\n\r\nlog4j.appender.stdout=org.apache.log4j.ConsoleAppender\r\nlog4j.appender.stdout.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.stdout.layout.ConversionPattern=%d; %-5p; (%F:%L); %m%n\r\n\r\nlog4j.appender.pgmlogfile=org.apache.log4j.FileAppender\r\nlog4j.appender.pgmlogfile.file=${LOGDIR}\/${LOGFILE}\r\nlog4j.appender.pgmlogfile.Append=true\r\nlog4j.appender.pgmlogfile.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.pgmlogfile.layout.ConversionPattern=%d %-5p; (%F:%L); %m%n\r\n<\/code><\/pre>\n<\/div>\n<p>This log4j property file will display the output to both the console\u00a0and save it to a log file. \u00a0In this example the output file is determined at runtime by evaluating the LOGDIR and the LOGFILE environment variables.<\/p>\n<p>The configuration format of log4j2 can still\u00a0support the old properties file style format, however, the contents of that file would be slightly different for version 2.<\/p>\n<p>Rather than trying to keep these two incompatible configuration files separate it is just as easy to switch over to the xml format that is supported by version 2.0 of log4j2.<\/p>\n<p>Note: XML isn&#8217;t really new as it was possible to have xml configuration files with version 1.2 of log4j.<\/p>\n<h2>Log4j version 2<\/h2>\n<p>Log4j2 will load its\u00a0configuration from a file, but now it supports so many possible formats there is a specific order that it will go through in an attempt to find the configuration file when one isn&#8217;t presented to it. \u00a0The first place it looks is if the<strong><em> log4j.configurationFile<\/em><\/strong> property is set in your virtual machine. When this is defined it will be used regardless\u00a0how the file is\u00a0named.<\/p>\n<p>When this property is not defined, then log4j will look for the config file in the classpath. \u00a0The default configuration file to use will be searched for using the following names in this order.<\/p>\n<div style=\"margin-left: 1cm;\"><code>log4j2-test.properties<br \/>\nlog4j2-test.yaml or log4j2-test.yml<br \/>\nlog4j2-test.json or log4j2-test.jsn<br \/>\nlog4j2-test.xml<br \/>\nlog4j2.properties<br \/>\nlog4j2.yaml or log4j2.yml<br \/>\nlog4j2.json or log4j2.jsn<br \/>\nlog4j2.xml<br \/>\n<\/code><\/div>\n<p>If no configuration file could be located the DefaultConfiguration will be used. This will cause logging output to go to the console. \u00a0The default configuration is not bad but by default it will only display errors or higher and only to the screen.<\/p>\n<h3>log4j2.xml<\/h3>\n<div class=\"sbody-code\">\n<pre><code>&lt;?xml version=\"1.0\" encoding=\"UTF-8\"?&gt;\r\n&lt;Configuration xmlns=\"http:\/\/logging.apache.org\/log4j\/2.0\/config\"&gt;\r\n\t&lt;Properties&gt;\r\n\t\t&lt;Property name=\"LOG_NAME\"&gt;logfile.log&lt;\/Property&gt;\r\n\t\t&lt;Property name=\"LOG_DIR\"&gt;${sys:LOGDIRECTORY}&lt;\/Property&gt;\r\n\t\t&lt;Property name=\"LOG_ARCHIVE\"&gt;${sys:LOGARCHIVE}&lt;\/Property&gt;\r\n\t\t&lt;Property name=\"ROLL_NAME\"&gt;logfile-%d-%i.log&lt;\/Property&gt;\r\n\t\t&lt;Property name=\"FILEPATTERN\"&gt;%-5p | %d{yyyy-MM-dd HH:mm:ss} | [%t] %C (%F:%L) - %m%n&lt;\/Property&gt;\r\n\t\t&lt;Property name=\"PATTERN\"&gt;%-5p | %C{2} (%F:%L) - %m%n&lt;\/Property&gt;\r\n\t&lt;\/Properties&gt;\r\n\t&lt;Appenders&gt;\r\n\t\t&lt;RollingFile name=\"ROLLINGFILE\" fileName=\"${LOG_DIR}\/${LOG_NAME}\" filePattern=\"${LOG_ARCHIVE}\/${ROLL_NAME}\" append=\"true\"&gt;\r\n\t\t&lt;PatternLayout pattern=\"${FILEPATTERN}\"\/&gt;\r\n\t\t&lt;Policies&gt;\r\n\t\t\t&lt;SizeBasedTriggeringPolicy size=\"1 KB\" \/&gt;\r\n\t\t&lt;\/Policies&gt;\r\n\t\t&lt;DefaultRolloverStrategy max=\"4\"\/&gt;\r\n\t&lt;\/RollingFile&gt;\r\n\t&lt;Console name=\"STDOUT\" target=\"SYSTEM_OUT\"&gt;\r\n\t\t&lt;PatternLayout pattern=\"${PATTERN}\"\/&gt;\r\n\t&lt;\/Console&gt;\r\n\t&lt;\/Appenders&gt;\r\n\r\n\t&lt;Loggers&gt;\r\n\t\t&lt;!-- add this line to get debug output for this particular class --&gt;\r\n\t\t&lt;Logger name=\"de.companyname.utility.Mymath\" level=\"debug\"\/&gt;\r\n\r\n\t\t&lt;Root level=\"info\"&gt;\r\n\t\t\t&lt;AppenderRef ref=\"STDOUT\"\/&gt;\r\n\t\t\t&lt;AppenderRef ref=\"ROLLINGFILE\"\/&gt;\r\n\t\t&lt;\/Root&gt;\r\n\t&lt;\/Loggers&gt;\r\n&lt;\/Configuration&gt;\r\n<\/code><\/pre>\n<\/div>\n<p>This configuration file is similar to the old log4j property file listed above. The output from level info or above will be output to both the screen and saved to a file. The format of the two different types of output can either use the same or a different format.\u00a0\u00a0In this case, the log file contains an extra date and time stamp per line.<\/p>\n<p>One other slight difference is that the log file will contain the full package and class name (%C) while the console output will only display a portion (%C{2}) of the package name. When the log file reaches 1 kilobyte, it will be renamed keeping up to four log files. Beyond that the oldest will be deleted. \u00a0This can obviously be changed to more realistic sizes in the megabytes.<\/p>\n<p>It might not be be obvious at the first glance but there is a neat little trick you can do as part of the rolling appender setup. \u00a0If we use a different directory as part of the filepattern then we are actually not only renaming the old files but moving them to a different directory when the file size reaches the maximum size.<\/p>\n<p>The only thing not fully explained is the following line.<\/p>\n<div class=\"sbody-code\">\n<pre><code>&lt;!-- add this line to get debug \r\noutput for this particular class --&gt;\r\n&lt;Logger name=\"de.companyname.utility.Mymath\" level=\"debug\"\/&gt;<\/code><\/pre>\n<\/div>\n<p><!-- add this line to get debug output for this particular class --><\/p>\n<p>The comment does rather give it away. Adding this line to our log4j2 properties actually will allow us to easily see the debug output for that particular class without turning on debugging for the entire program.<\/p>\n<p>One final difference between the old and new version of log4j is how properties inside of the configuration file are treated. \u00a0To access the JVM values it is necessary to prefix them\u00a0with &#8220;sys:&#8221;.<\/p>\n<p>It is not necessary to define everything as a property as is done in this example. \u00a0However, doing so does show the contrast between the JVM values and standard properties.<\/p>\n<h2>Sample program<\/h2>\n<p><strong>Program.java<\/strong><\/p>\n<div class=\"sbody-code\">\n<pre><code>package de.companyname.utility;\r\n\r\nimport org.apache.logging.log4j.LogManager;\r\nimport org.apache.logging.log4j.Logger;\r\n\r\npublic class Program {\r\n\r\n\tstatic Logger logfile = LogManager.getLogger(Program.class.getName());\r\n\t\r\n\tpublic static void main(String[] args) \r\n\t{\r\n\t\tlogfile.info(\"Program starting at \" + \"\");\r\n\t\tlogfile.trace(\"add a trace to log output\");\r\n\t\t\r\n\t\tfor (int index = 1; index &lt;= 5; index++)\r\n\t\t{\r\n\t\t\ttry {\r\n\t\t\t\tint square = \r\nde.companyname.utility.Mymath.square(index);\r\n\t\t\t\tlogfile.info(index + \" x \" + index + \" = \" + \r\nsquare);\r\n\t\t\t}\r\n\t\t\tcatch (Exception ex)\r\n\t\t\t{\r\n\t\t\t\tlogfile.fatal(\" while processing value \" + \r\nindex);\r\n\t\t\t\tlogfile.fatal(ex.getMessage());\r\n\t\t\t}\r\n\t\t}\r\n\t\t\r\n\t\tlogfile.debug(\"add some additional debug to output\");\r\n\t\tlogfile.info(\"Program finishing at \" + \"\");\r\n\t}\r\n}<\/code><\/pre>\n<\/div>\n<p>&nbsp;<\/p>\n<p><strong>Mymath.java<\/strong><\/p>\n<div class=\"sbody-code\">\n<pre><code>package de.companyname.utility;\r\n\r\nimport org.apache.logging.log4j.LogManager;\r\nimport org.apache.logging.log4j.Logger;\r\n\r\npublic class Mymath {\r\n\r\n\t\/*\r\n\t * will return the square of the value input.\r\n\t * this method will only be for the range of positive numbers.\r\n\t *\/\r\n\tstatic public int square (int value) throws Exception\r\n\t{\r\n\t\tLogger logfile = LogManager.getLogger(Mymath.class.getName());\r\n\t\t\r\n\t\tlogfile.debug(\"entering square\");\r\n\t\tlogfile.debug(\"parameter is \" + value);\r\n\t\tint retval = 0;\r\n\t\t\r\n\t\tif (value &gt; 0)\r\n\t\t\tretval = value * value;\r\n\t\telse\r\n\t\t{\r\n\t\t\tlogfile.debug(\"invalid value of \" + value + \" given\");\r\n\t\t}\r\n\t\t\r\n\t\tlogfile.debug(\"leaving square\");\r\n\t\treturn retval;\r\n\t}\r\n}<\/code><\/pre>\n<\/div>\n<p>&nbsp;<\/p>\n<p><strong>runProgram.sh<\/strong><\/p>\n<div class=\"sbody-code\">\n<pre><code>#!\/bin\/bash\r\n\r\nVMARGS=\"-DLOGDIRECTORY=log -DLOGARCHIVE=archive -Dlog4j.configurationFile=resources\/log4j2.xml -DLOGARCHIVE=archive -DLOGDIRECTORY=log\"\r\nCP=lib\/log4j-api-2.6.2.jar:lib\/log4j-core-2.6.2.jar:.\r\nPGM=de.companyname.utility.Program\r\n\r\nmkdir log\r\nmkdir archive\r\n\r\nCMD=\"java -cp $CP $VMARGS $PGM\"\r\n\r\necho $CMD\r\n$CMD\r\n<\/code><\/pre>\n<\/div>\n<p>&nbsp;<\/p>\n<h2>Output<\/h2>\n<p>With no debugging enabled, the program simply outputs the information messages from the main program.<\/p>\n<p>2016-08-25 17:23:58 | INFO | utility.Program (Program.java:13) &#8211; Program starting at<br \/>\n2016-08-25 17:23:58 | INFO | utility.Program (Program.java:20) &#8211; 1 x 1 = 1<br \/>\n2016-08-25 17:23:58 | INFO | utility.Program (Program.java:20) &#8211; 2 x 2 = 4<br \/>\n2016-08-25 17:23:58 | INFO | utility.Program (Program.java:20) &#8211; 3 x 3 = 9<br \/>\n2016-08-25 17:23:58 | INFO | utility.Program (Program.java:20) &#8211; 4 x 4 = 16<br \/>\n2016-08-25 17:23:58 | INFO | utility.Program (Program.java:20) &#8211; 5 x 5 = 25<br \/>\n2016-08-25 17:23:58 | INFO | utility.Program (Program.java:30) &#8211; Program finishing at<\/p>\n<p>It is possible to see the debug output from square method in the Mymath class by adding this to the log4j2 xml file.<\/p>\n<pre><code>&lt;Logger name=\"de.companyname.utility.Mymath\" level=\"debug\"\/&gt;<\/code><\/pre>\n<p>2016-08-25 17:10:38 | INFO | utility.Program (Program.java:13) &#8211; Program starting at<br \/>\n2016-08-25 17:10:38 | DEBUG | utility.Mymath (Mymath.java:16) &#8211; entering square<br \/>\n2016-08-25 17:10:38 | DEBUG | utility.Mymath (Mymath.java:17) &#8211; parameter is 1<br \/>\n2016-08-25 17:10:38 | DEBUG | utility.Mymath (Mymath.java:27) &#8211; leaving square<br \/>\n2016-08-25 17:10:38 | INFO | utility.Program (Program.java:20) &#8211; 1 x 1 = 1<\/p>\n<h2><strong>&#8230;<\/strong><\/h2>\n<p>2016-08-25 17:10:38 | INFO | utility.Program (Program.java:20) &#8211; 4 x 4 = 16<br \/>\n2016-08-25 17:10:38 | DEBUG | utility.Mymath (Mymath.java:16) &#8211; entering square<br \/>\n2016-08-25 17:10:38 | DEBUG | utility.Mymath (Mymath.java:17) &#8211; parameter is 5<br \/>\n2016-08-25 17:10:38 | DEBUG | utility.Mymath (Mymath.java:27) &#8211; leaving square<br \/>\n2016-08-25 17:10:38 | INFO | utility.Program (Program.java:20) &#8211; 5 x 5 = 25<br \/>\n2016-08-25 17:10:38 | INFO | utility.Program (Program.java:30) &#8211; Program finishing at<\/p>\n<p>If the goal was to see either all debug output in the entire program or to reduce the output to only errors and above then simply change the root level (ie. debug or error).<\/p>\n<pre><code>\t&lt;Root level=\"<strong><span style=\"color: #ff0000;\">info<\/span><\/strong>\"&gt;\r\n\t\t&lt;AppenderRef ref=\"STDOUT\"\/&gt;\r\n\t\t&lt;AppenderRef ref=\"ROLLINGFILE\"\/&gt;\r\n\t&lt;\/Root&gt;<\/code><\/pre>\n<p>All of this is standard log4j2 which is both easy to use and easy to understand. \u00a0It is also possible to create new log levels and filter using them as well. \u00a0That will be covered in part III\u00a0on log4j2.<\/p>\n<h3>Apache Log4j2 documentation<br \/>\n<a href=\"http:\/\/logging.apache.org\/log4j\/2.0\/log4j-users-guide.pdf\">logging.apache.org\/log4j\/2.0\/log4j-users-guide.pdf<\/a><\/h3>\n<p>Note: The\u00a0example was compiled with java 1.8 and uses log4j-api-2.6.2.jar and log4j-core-2.6.2.jar.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>However, Just like with computers, cars and women there is always a faster, bigger, or better model on the horizon. Version 1.2 of log4j has reached its end of life on August 5th 2015 but there is a version 2 &hellip; <a href=\"https:\/\/blog.paranoidprofessor.com\/index.php\/2016\/09\/01\/better-logging-than-printf-using-log4j-part-ii\/\">Continue reading <span class=\"meta-nav\">&rarr;<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[20],"tags":[73,12,78],"_links":{"self":[{"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1077"}],"collection":[{"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/comments?post=1077"}],"version-history":[{"count":18,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1077\/revisions"}],"predecessor-version":[{"id":1196,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1077\/revisions\/1196"}],"wp:attachment":[{"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/media?parent=1077"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/categories?post=1077"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/tags?post=1077"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}