{"id":1213,"date":"2016-09-04T20:16:29","date_gmt":"2016-09-04T20:16:29","guid":{"rendered":"http:\/\/blog.paranoidprofessor.com\/?p=1213"},"modified":"2016-09-04T20:16:29","modified_gmt":"2016-09-04T20:16:29","slug":"better-logging-than-printf-using-log4j-part-iii","status":"publish","type":"post","link":"https:\/\/blog.paranoidprofessor.com\/index.php\/2016\/09\/04\/better-logging-than-printf-using-log4j-part-iii\/","title":{"rendered":"better logging than printf – using log4j – part III"},"content":{"rendered":"

Log4j is a very convenient tool to have in your programming arsenal. \u00a0This is true even if only the very basic functionality is being used. \u00a0 \u00a0The basic functionality of log4j2 was covered in my previous example.<\/p>\n

To be honest, the standard levels are truly good enough for most applications but the neat feature of version 2 is the ability to create custom output levels.<\/p>\n

In order to create some new levels we do need to know how the existing levels relate to each other.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n
Standard Level<\/th>\nInteger value<\/th>\n<\/tr>\n
OFF<\/td>\n0<\/td>\n<\/tr>\n
FATAL<\/td>\n100<\/td>\n<\/tr>\n
ERROR<\/td>\n200<\/td>\n<\/tr>\n
WARN<\/td>\n300<\/td>\n<\/tr>\n
INFO<\/td>\n400<\/td>\n<\/tr>\n
DEBUG<\/td>\n500<\/td>\n<\/tr>\n
TRACE<\/td>\n600<\/td>\n<\/tr>\n
ALL<\/td>\nInteger.MAX_VALUE<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

From looking at these levels there is quite a bit of space between each integer value for a new level to be slipped in. \u00a0These levels could be developer or site specific. \u00a0They could even be used to help track information for other internal needs (ie auditing).<\/p>\n

To provide an example of this, I will create two new levels, one being to generate a silly amount of debug information while the other would be to capture auditing information.<\/p>\n

Custom Levels<\/h2>\n

Actually very little extra work is necessary to create new levels. \u00a0Simply use the new Level class to create a new level. \u00a0Simply decide where in the range of values the value should fit in.<\/p>\n

Create new level<\/h3>\n
\n
Level AUDIT = Level.forName(\"AUDIT\",350);\r\nLevel SPECIAL = Level.forName(\"SPECIAL\", 399);<\/code><\/pre>\n<\/div>\n
Apache also provides us with a new method on the Logger to call when using the new level. The method “log” accepts the new level as the first parameter followed by the data\u00a0to be logged.<\/p>\n
Using new level<\/h3>\n
\n
logfile.log(AUDIT, \"first auditing message\");\r\nlogfile.log(AUDIT, \"second auditing message\");<\/code><\/pre>\n<\/div>\n
There is really not a lot of special handling that is necessary when using these new levels but it is important that the new log levels are created before retrieving the logger from the LogManager.<\/p>\n
Examining the output<\/h2>\n
The full program and configuration file listing is at the bottom. \u00a0What is\u00a0more interesting is looking at some of the output that would be generated by modifying the log4j2.xml file especially when we change the root level.<\/p>\n
The most basic setting\u00a0is to just use the normal info level.<\/p>\n
<Root level=”info”>
\n<AppenderRef ref=”STDOUT” \/>
\n<AppenderRef ref=”FILE” \/>
\n<\/Root><\/p><\/blockquote>\n
\n
We can see in our log output that one of our new debug levels, AUDIT, is now showing up in the middle of our log output. \u00a0This might not be appropriate for real auditing but might be useful for some sort of diagnostics for special hardware or special situations.<\/p>\n<\/div>\n
\n
2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:18) - Program starting at \r\n2016-09-02 21:22:56 | AUDIT | utility.CustomVersion (CustomVersion.java:21) - first auditing message\r\n2016-09-02 21:22:56 | AUDIT | utility.CustomVersion (CustomVersion.java:22) - second auditing message\r\n2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 1 x 1 = 1\r\n2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 2 x 2 = 4\r\n2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 3 x 3 = 9\r\n2016-09-02 21:22:56 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '4'\r\n2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 4 x 4 = 16\r\n2016-09-02 21:22:56 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '5'\r\n2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 5 x 5 = 25\r\n2016-09-02 21:22:56 | INFO  | utility.CustomVersion (CustomVersion.java:40) - Program finishing at \r\n<\/code><\/pre>\n<\/div>\n
The most interesting change to the output was when setting the level in our configuration file to our new custom level – “audit”. \u00a0This actually performed as a filter for that level and only that level in the the output.<\/p>\n
This was pretty neat as by default log4j2 doesn’t know anything about our new level when it reads in the configuration file.<\/p>\n
<Root level=”audit”>
\n<AppenderRef ref=”STDOUT” \/>
\n<AppenderRef ref=”FILE” \/>
\n<\/Root><\/p><\/blockquote>\n
\n
2016-09-02 21:24:23 | AUDIT | utility.CustomVersion (CustomVersion.java:21) - first auditing message\r\n2016-09-02 21:24:23 | AUDIT | utility.CustomVersion (CustomVersion.java:22) - second auditing message\r\n2016-09-02 21:24:23 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '4'\r\n2016-09-02 21:24:23 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '5'\r\n<\/code><\/pre>\n<\/div>\n
Finally when changing the filter level to all we will see all log output including our two new levels. \u00a0You can see both AUDIT and the SILLYDEBUG levels as expected.<\/p>\n
<Root level=”all”>
\n<AppenderRef ref=”STDOUT” \/>
\n<AppenderRef ref=”FILE” \/>
\n<\/Root><\/p><\/blockquote>\n
\n
2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:18) - Program starting at                                                                                                                                                                              \r\n2016-09-02 21:25:09 | TRACE | utility.CustomVersion (CustomVersion.java:19) - add a trace to log output                                                                                                                                                                        \r\n2016-09-02 21:25:09 | AUDIT | utility.CustomVersion (CustomVersion.java:21) - first auditing message                                                                                                                                                                           \r\n2016-09-02 21:25:09 | AUDIT | utility.CustomVersion (CustomVersion.java:22) - second auditing message                                                                                                                                                                          \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square                                                                                                                                                                                 \r\n2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 1                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 1                                                                                                                                                                   \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square                                                                                                                                                                                  \r\n2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 1 x 1 = 1                                                                                                                                                                                        \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square                                                                                                                                                                                 \r\n2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 2                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 2                                                                                                                                                                   \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square                                                                                                                                                                                  \r\n2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 2 x 2 = 4                                                                                                                                                                                        \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square                                                                                                                                                                                 \r\n2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 3                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 3                                                                                                                                                                   \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square                                                                                                                                                                                  \r\n2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 3 x 3 = 9                                                                                                                                                                                        \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square                                                                                                                                                                                 \r\n2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 4                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 4                                                                                                                                                                   \r\n2016-09-02 21:25:09 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '4'                                                                                                                                             \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square                                                                                                                                                                                  \r\n2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 4 x 4 = 16                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square                                                                                                                                                                                 \r\n2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 5                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 5                                                                                                                                                                   \r\n2016-09-02 21:25:09 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '5'                                                                                                                                             \r\n2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square                                                                                                                                                                                  \r\n2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:28) - 5 x 5 = 25                                                                                                                                                                                       \r\n2016-09-02 21:25:09 | DEBUG | utility.CustomVersion (CustomVersion.java:39) - add some additional debug to output                                                                                                                                                              \r\n2016-09-02 21:25:09 | INFO  | utility.CustomVersion (CustomVersion.java:40) - Program finishing at                                                                                                                                                                             <\/code><\/pre>\n<\/div>\n
Other discoveries<\/h2>\n
One rather interesting thing about these custom levels was how forgiving log4j2 seemed to be of levels that did not exist.<\/p>\n
During my testing I accidentally created an unknown level due to a typo only to discover that that message was silently ignored.\u00a0If I then created the level prior to it being used, the level functioned as exactly as it should. \u00a0It is not clear if this is a bug or a feature.<\/p>\n
I made another interesting discovery while fooling around with Apache\u00a0Ant. \u00a0It was surprising not to see the file and line number in my log output. \u00a0It took a few minutes of head scratching to realize that the program was not compiled with debugging on.<\/p>\n
\n
DEBUG | 2016-08-30 23:08:56 | [main] de.companyname.helloworld.HelloWorld (null:-1) - HelloWorld starting\r\nINFO  | 2016-08-30 23:08:56 | [main] de.companyname.helloworld.HelloWorld (null:-1) - Hello World!\r\nDEBUG | 2016-08-30 23:08:56 | [main] de.companyname.helloworld.HelloWorld (null:-1) - HelloWorld finishing\r\n<\/code><\/pre>\n<\/div>\n
The solution was easy enough. \u00a0Simply change the ant script to turn on debugging while compiling and recompile\u00a0the\u00a0program.<\/p>\n
Test program<\/h2>\n
CustomProgram.java<\/strong><\/p>\n
\n
package de.companyname.utility;\r\n\r\n\r\nimport org.apache.logging.log4j.Level;\r\nimport org.apache.logging.log4j.LogManager;\r\nimport org.apache.logging.log4j.Logger;\r\n\r\n\r\npublic class CustomVersion {\r\n\r\n\tstatic Level AUDIT = Level.forName(\"AUDIT\",350);\r\n\tstatic Level SPECIAL = Level.forName(\"SPECIAL\", 399);\r\n\t\r\n\tpublic static void main(String[] args) \r\n\t{\r\n\t\tLogger logfile = LogManager.getLogger(CustomVersion.class.getName());\r\n\t\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\tlogfile.log(AUDIT, \"first auditing message\");\r\n\t\tlogfile.log(AUDIT, \"second auditing message\");\r\n\t\t\r\n\t\tfor (int index = 1; index <= 5; index++)\r\n\t\t{\r\n\t\t\ttry {\r\n\t\t\t\tint square = de.companyname.utility.CustomMathV.square(index);\r\n\t\t\t\tlogfile.info(index + \" x \" + index + \" = \" + square);\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 \" + index);\r\n\t\t\t\tlogfile.fatal(ex.getMessage());\r\n\t\t\t}\r\n\t\t}\r\n\r\n\t\tlogfile.log(Level.getLevel(\"UNDEFINED\"), \"some xxxx message\"); \r\n\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
CustomMathV.java<\/b><\/p>\n
\n
package de.companyname.utility;\r\n\r\n\r\nimport org.apache.logging.log4j.Level;\r\nimport org.apache.logging.log4j.LogManager;\r\nimport org.apache.logging.log4j.Logger;\r\n\r\npublic class CustomMathV {\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\tLevel AUDIT = Level.forName(\"AUDIT\", 350);\r\n\t\tLevel SILLYDEBUG = Level.forName(\"SILLYDEBUG\", 9999); \r\n\t\tLogger logfile = LogManager.getLogger(CustomMathV.class.getName());\r\n\t\t\r\n\t\tlogfile.log(SILLYDEBUG, \"entering square\");\r\n\t\tlogfile.debug(\"parameter is \" + value);\r\n\t\t\r\n\t\tlogfile.log(SILLYDEBUG,  \"mathmatics of squared using \" + value);\r\n\t\tint retval = 0;\r\n\t\t\r\n\t\tif (value > 0)\r\n\t\t{\r\n\t\t\tretval = value * value;\r\n\t\t\tif (value >= 4)\r\n\t\t\t\tlogfile.log(AUDIT,\"extremely large numbers being used in math - value = '\" + value + \"'\");\r\n\t\t}\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.log(SILLYDEBUG, \"exiting square\");\r\n\t\treturn retval;\r\n\t}\r\n}<\/code><\/pre>\n<\/div>\n
log4j2-custom.xml<\/b><\/p>\n
\n
<?xml version=\"1.0\" encoding=\"UTF-8\"?>\r\n<Configuration xmlns=\"http:\/\/logging.apache.org\/log4j\/2.0\/config\">\r\n\r\n\t<Properties>\r\n\t\t<Property name=\"LOG_NAME\">logfile.log<\/Property>\r\n\t\t<Property name=\"FILEPATTERN\">%-5p | %d{yyyy-MM-dd HH:mm:ss} | [%t] %C (%F:%L) - %m%n<\/Property>\r\n\t\t<Property name=\"PATTERN\">%d{yyyy-MM-dd HH:mm:ss} | %-5p | %C{2} (%F:%L) - %m%n<\/Property>\r\n\t<\/Properties>\r\n\r\n\t<Appenders>\r\n\t\t<File name=\"FILE\" fileName=\"${LOG_NAME}\" append=\"true\">\r\n\t\t\t<PatternLayout pattern=\"${FILEPATTERN}\"\/>\r\n\t\t<\/File>\r\n\t\t<Console name=\"STDOUT\" target=\"SYSTEM_OUT\">\r\n\t\t\t<PatternLayout pattern=\"${PATTERN}\"\/>\r\n\t\t<\/Console>\r\n\t<\/Appenders>\r\n\r\n\t<Loggers>\r\n\t\t<!-- add this line to get debug output for this particular class -->\r\n\t\t<Logger name=\"dex.companyname.utility.Mymath\" level=\"debug\"\/>\r\n\t\t<Logger name=\"dex.companyname.utility.CustomMath\" level=\"debug\"\/>\r\n\r\n\t\t<Root level=\"info\">\r\n\t\t\t<AppenderRef ref=\"STDOUT\" \/>\r\n\t\t\t<AppenderRef ref=\"FILE\" \/>\r\n\t\t<\/Root>\r\n\t<\/Loggers>\r\n\r\n<\/Configuration>\r\n<\/code><\/pre>\n<\/div>\n
runProgram.sh<\/strong><\/p>\n
\n
#!\/bin\/bash\r\n\r\nVMARGS=\"-Dlog4j.configurationFile=resources\/log4j2-custom.xml \"\r\nCP=\/tmp\/version3\/lib\/log4j-api-2.6.2.jar:\/tmp\/version3\/lib\/log4j-core-2.6.2.jar:.\r\nPGM=de.companyname.utility.CustomVersion\r\n\r\nCMD=\"java -cp $CP $VMARGS $PGM\"\r\n\r\necho $CMD\r\n$CMD\r\n<\/code><\/pre>\n<\/div>\n
References
\nhttp:\/\/logging.apache.org\/log4j\/2.x\/manual\/customloglevels.html<\/a><\/h3>\n
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":"
Log4j is a very convenient tool to have in your programming arsenal. \u00a0This is true even if only the very basic functionality is being used. \u00a0 \u00a0The basic functionality of log4j2 was covered in my previous example. To be honest, … Continue reading →<\/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\/1213"}],"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=1213"}],"version-history":[{"count":3,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1213\/revisions"}],"predecessor-version":[{"id":1216,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/posts\/1213\/revisions\/1216"}],"wp:attachment":[{"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/media?parent=1213"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/categories?post=1213"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.paranoidprofessor.com\/index.php\/wp-json\/wp\/v2\/tags?post=1213"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}