{"id":1067,"date":"2016-08-29T20:44:48","date_gmt":"2016-08-29T20:44:48","guid":{"rendered":"http:\/\/blog.paranoidprofessor.com\/?p=1067"},"modified":"2016-09-02T18:53:36","modified_gmt":"2016-09-02T18:53:36","slug":"better-logging-than-printf-using-log4j-part-i","status":"publish","type":"post","link":"https:\/\/blog.paranoidprofessor.com\/index.php\/2016\/08\/29\/better-logging-than-printf-using-log4j-part-i\/","title":{"rendered":"better logging than printf &#8211; using log4j &#8211; part I"},"content":{"rendered":"<h2>The old way<\/h2>\n<p>Log files or debugging can be done using print statements. \u00a0It is a very rudimentary way to see some of your internal variables or to have a log of how the program run went.<\/p>\n<p>This printf sample can turn off the debugging with a single variable. \u00a0It is not too difficult\u00a0to set this value as a parameter to the program but it is really just too much effort for such simple control. \u00a0It is a all or nothing that is not so satisfying.<\/p>\n<p>It is however, much better than not having any ability to log or debug the program in question.<\/p>\n<div class=\"sbody-code\">\n<pre><code>public class Program  {\r\n\r\n\tboolean debug = true;\r\n\tpublic Program()\r\n\t{\r\n\t}\r\n\tpublic void performWork()\r\n\t{\r\n\t\tint index = 0;\r\n\t\tSystem.out.println(\"Interface 'Program' starting\");\r\n\r\n\t\tfor (index = 1; index &lt;= 10; index++)\r\n\t\t{\r\n\t\t\tint square = index * index;\r\n\t\t\tif (debug == true)\r\n\t\t\t\tSystem.out.println(index + \" x \" + index + \" = \" + square);\r\n\t\t\tSystem.out.println(\"square is \" + square);\r\n\t\t}\r\n\t\tSystem.out.println(\"Interface 'Program' finished\");\r\n\t}\r\n\tpublic static void main(String args[])\r\n\t{\r\n\t\tProgram helper = new Program();\r\n\t\thelper.performWork();\r\n\t}\r\n}<\/code>\r\n<\/pre>\n<\/div>\n<h2>&#8220;Printf&#8221; logfile output<\/h2>\n<div style=\"margin-left: 1cm;\"><code>Interface 'Program' starting<br \/>\n1 x 1 = 1<br \/>\nsquare is 1<br \/>\n2 x 2 = 4<br \/>\nsquare is 4<br \/>\n3 x 3 = 9<br \/>\nsquare is 9<br \/>\n4 x 4 = 16<br \/>\nsquare is 16<br \/>\n5 x 5 = 25<br \/>\nsquare is 25<br \/>\n6 x 6 = 36<br \/>\nsquare is 36<br \/>\n7 x 7 = 49<br \/>\nsquare is 49<br \/>\n8 x 8 = 64<br \/>\nsquare is 64<br \/>\n9 x 9 = 81<br \/>\nsquare is 81<br \/>\n10 x 10 = 100<br \/>\nsquare is 100<br \/>\nInterface 'Program' finished<\/code><\/div>\n<div style=\"margin-left: 1cm;\"><\/div>\n<p>This output may have been acceptable back in computer class but it really doesn&#8217;t measure up in a production environment. \u00a0True, we see the output, both the standard\u00a0and debug output, however,\u00a0this output could have been from version 1 of our program six months ago or version 3 yesterday.<\/p>\n<p>Fortunately, better logging and debug output has been solved quite elegantly by the <a href=\"https:\/\/logging.apache.org\/log4j\/2.x\/\">Log4j project at Apache<\/a>.<\/p>\n<p>The really clever thing about their\u00a0solution is that all of the logging\/debugging is controlled via a tiny configuration file. \u00a0Write your program to read in the configuration file and then use the log4j output methods. \u00a0Changing the configuration file changes the nature of the log output.<\/p>\n<p>The object is &#8220;Logger&#8221; has a few methods each of which can be used in lieu of printf.<\/p>\n<ul>\n<li>debug<\/li>\n<li>info<\/li>\n<li>warn<\/li>\n<li>error<\/li>\n<li>fatal<\/li>\n<\/ul>\n<p>Each of these are actually treated as a different level with each all inclusive of all levels before\u00a0it. \u00a0The real beauty is Log4j allows you to filter which level of output you wish to see. Log4j supports date, displays debug level, class file and line number if you really need it.<\/p>\n<p>This alone is more than enough reason to use log4j to help control logging but there is more. \u00a0It is possible to route the output to a file, the console or both.<\/p>\n<div class=\"sbody-code\">\n<pre><code># Root logger option\r\nlog4j.rootLogger=<span style=\"color: #ff0000;\">debug<\/span>, terminal\r\n\r\n# Redirect log messages \r\n<strong>log4j.appender.terminal=org.apache.log4j.ConsoleAppender\r\nlog4j.appender.terminal.Target=System.out\r\n<\/strong>log4j.appender.terminal.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.terminal.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n<\/code><\/pre>\n<\/div>\n<p>The highlighted lines set the output to the screen. \u00a0The last two lines allow for some customization how the output looks. \u00a0\u00a0The rootLogger sets what level to filter at. \u00a0Simply edit the property file to the level of logging that you wish to see. \u00a0The filter is set to &#8220;debug&#8221; so all logging output (debug,info,warn, error and fatal) will be displayed.<\/p>\n<h2>The new way with log4j and property files<\/h2>\n<p>The next sample program\u00a0is virtually no different than the printf version for outputting log details.<\/p>\n<p>In the constructor, in this example, the PropertyConfigurator object is used to load the log4j.properties file from the current directory. \u00a0Log4j will be clever enough to do all the setup in the background after reading the property file.<\/p>\n<p><strong>ConfigFileLog4j.java<\/strong><\/p>\n<div class=\"sbody-code\">\n<pre><code>import org.apache.log4j.Logger;\r\nimport org.apache.log4j.PropertyConfigurator;\r\n\r\npublic class ConfigFileLog4j {\r\n\r\n\tLogger logfile = null;\r\n\t\r\n\tpublic ConfigFileLog4j()\r\n\t{\r\n\t\t\/\/ get a handle to \"logger\"\r\n\t\tPropertyConfigurator.configure(\"log4j.properties\");\r\n\t\tlogfile = Logger.getLogger(ConfigFileLog4j.class);\r\n\t}\r\n\tpublic void performWork()\r\n\t{\r\n\t\tint index = 0;\r\n\t\tlogfile.info(\"Interface 'ConfigFileLog4j' starting\");\r\n\r\n\t\tfor (index = 1; index &lt;= 10; index++)\r\n\t\t{\r\n\t\t\tint square = index * index;\r\n\t\t\tlogfile.debug(index + \" x \" + index + \" = \" + square);\r\n\t\t\tlogfile.info(\"square is \" + square);\r\n\t\t}\r\n\t\tlogfile.info(\"Interface 'ConfigFileLog4j' finished\");\r\n\t}\r\n\tpublic static void main(String args[])\r\n\t{\r\n\t\tConfigFileLog4j helper = new ConfigFileLog4j();\r\n\t\thelper.performWork();\r\n\t}\r\n}\r\n<\/code><\/pre>\n<\/div>\n<p>&nbsp;<\/p>\n<h2>Log4j logfile\u00a0output<\/h2>\n<p>This sample output is done with the filter set to &#8220;info&#8221; thus giving us the output that we probably want to see from a normal run.<\/p>\n<div style=\"margin-left: 1cm;\"><code>2016-07-10 23:08:38 INFO ConfigFileLog4j:22 - Interface 'ConfigFileLog4j' starting<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 1<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 4<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 9<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 16<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 25<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 36<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 49<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 64<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 81<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:28 - square is 100<br \/>\n2016-07-10 23:08:38 INFO ConfigFileLog4j:30 - Interface 'ConfigFileLog4j' finished<br \/>\n<\/code><\/div>\n<p>This is probably the easiest way to use log4j. \u00a0Simply include the property file with the program, change the property file as necessary during development.<\/p>\n<p>This is good because if an unruly client or IT department needs a different format or wishes to reduce the logging this can be achieved by simply modifying the configuration file not changing and recompiling the program itself.<\/p>\n<p>It is possible to display the output purely to the console when running.<\/p>\n<div class=\"sbody-code\">\n<pre><code>log4j.rootLogger=debug<code>, terminal\r\n\r\n# console setup\r\nlog4j.appender.terminal=org.apache.log4j.ConsoleAppender\r\nlog4j.appender.terminal.Target=System.out\r\nlog4j.appender.terminal.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.terminal.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n<\/code><\/code><\/pre>\n<\/div>\n<p>However, once the program is fully bug free, you can ignore the console and simply write all output to the log file.<\/p>\n<div class=\"sbody-code\">\n<pre><code>log4j.rootLogger=debug, file\r\n\r\n# Redirect log messages to a log file\r\nlog4j.appender.file=org.apache.log4j.RollingFileAppender\r\nlog4j.appender.file.file=${LOGDIR}\/${LOGFILE}\r\nlog4j.appender.file.MaxFileSize=10mb\r\nlog4j.appender.file.MaxBackupIndex=3 \r\nlog4j.appender.file.Append=true \r\nlog4j.appender.file.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n<\/code><\/pre>\n<\/div>\n<p>There are actually a couple of nifty things that you can do when writing the output to log files. \u00a0The first is that you can decide on the maximum log file size as well as how many old copies of the logs to keep. \u00a0Once the logfile reaches this size it automatically moves the current logfile to logfile.1 &#8211; if necessary renaming all of the log files to a newer version\u00a0until all the logs are renamed and then resumes writing the output to the log file.<\/p>\n<p>In the above property file the output is set to Append. \u00a0This will simply append future program output to the end of the log file. \u00a0This is really handy to easily see the history of a given program at a glance.<\/p>\n<p>In my opinion one of the more interesting things that you can do with log files is you can use values from the java virtual machine, in this case LOGDIR and LOGFILE, to determine some of the functionality.<\/p>\n<p>This may not be necessary in most cases but perhaps for a situation where multiple related program s utilizes a single property file this might come in handy.<\/p>\n<p>It is even possible to have a single log4j property file that is designed to output to both the screen and save to the log file.<\/p>\n<div class=\"sbody-code\">\n<pre><code>log4j.rootLogger=debug, file, terminal\r\n\r\n# console setup\r\nlog4j.appender.terminal=org.apache.log4j.ConsoleAppender\r\nlog4j.appender.terminal.Target=System.out\r\nlog4j.appender.terminal.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.terminal.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n\r\n\r\n# file setup\r\nlog4j.appender.file=org.apache.log4j.RollingFileAppender\r\nlog4j.appender.file.file=${LOGDIR}\/${LOGFILE}\r\nlog4j.appender.file.MaxFileSize=10mb\r\nlog4j.appender.file.MaxBackupIndex=3 \r\nlog4j.appender.file.Append=true \r\nlog4j.appender.file.layout=org.apache.log4j.PatternLayout\r\nlog4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%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\nCP=lib\/log4j-1.2.17.jar:.\r\nPGM=ConfigFileLog4j\r\n\r\nmkdir log\r\n\r\nCMD=\"java -DLOGFILE=custom.log -DLOGDIR=log -cp $CP $PGM\"\r\n\r\necho $CMD\r\n$CMD\r\n<\/code><\/pre>\n<\/div>\n<p>Unfortunately this shouldn&#8217;t really be called the new way of doing things. \u00a0Just recently, in 2013, a newer better version of Log4j came out. \u00a0This will be the subject of<a href=\"http:\/\/blog.paranoidprofessor.com\/index.php\/2016\/09\/01\/better-logging-than-printf-using-log4j-part-ii\/\"> part II <\/a>of this article.<\/p>\n<p>Note:\u00a0This example was compiled with java 1.7 and uses log4j-1.2.17.jar<\/p>\n<p>Note:\u00a0This example was also compiled with java 1.8 and uses log4j-1.2.17.jar<\/p>\n","protected":false},"excerpt":{"rendered":"<p>The old way Log files or debugging can be done using print statements. \u00a0It is a very rudimentary way to see some of your internal variables or to have a log of how the program run went. This printf sample &hellip; <a href=\"https:\/\/blog.paranoidprofessor.com\/index.php\/2016\/08\/29\/better-logging-than-printf-using-log4j-part-i\/\">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\/1067"}],"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=1067"}],"version-history":[{"count":18,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1067\/revisions"}],"predecessor-version":[{"id":1193,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1067\/revisions\/1193"}],"wp:attachment":[{"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/media?parent=1067"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/categories?post=1067"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/tags?post=1067"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}