Log4j is a very convenient tool to have in your programming arsenal. This is true even if only the very basic functionality is being used. The basic functionality of log4j2 was covered in my previous example.
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.
In order to create some new levels we do need to know how the existing levels relate to each other.
| Standard Level | Integer value |
|---|---|
| OFF | 0 |
| FATAL | 100 |
| ERROR | 200 |
| WARN | 300 |
| INFO | 400 |
| DEBUG | 500 |
| TRACE | 600 |
| ALL | Integer.MAX_VALUE |
From looking at these levels there is quite a bit of space between each integer value for a new level to be slipped in. These levels could be developer or site specific. They could even be used to help track information for other internal needs (ie auditing).
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.
Custom Levels
Actually very little extra work is necessary to create new levels. Simply use the new Level class to create a new level. Simply decide where in the range of values the value should fit in.
Create new level
Level AUDIT = Level.forName("AUDIT",350);
Level SPECIAL = Level.forName("SPECIAL", 399);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 to be logged.
Using new level
logfile.log(AUDIT, "first auditing message");
logfile.log(AUDIT, "second auditing message");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.
Examining the output
The full program and configuration file listing is at the bottom. What is more 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.
The most basic setting is to just use the normal info level.
<Root level=”info”>
<AppenderRef ref=”STDOUT” />
<AppenderRef ref=”FILE” />
</Root>
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. This might not be appropriate for real auditing but might be useful for some sort of diagnostics for special hardware or special situations.
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:18) - Program starting at
2016-09-02 21:22:56 | AUDIT | utility.CustomVersion (CustomVersion.java:21) - first auditing message
2016-09-02 21:22:56 | AUDIT | utility.CustomVersion (CustomVersion.java:22) - second auditing message
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:28) - 1 x 1 = 1
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:28) - 2 x 2 = 4
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:28) - 3 x 3 = 9
2016-09-02 21:22:56 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '4'
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:28) - 4 x 4 = 16
2016-09-02 21:22:56 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '5'
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:28) - 5 x 5 = 25
2016-09-02 21:22:56 | INFO | utility.CustomVersion (CustomVersion.java:40) - Program finishing at
The most interesting change to the output was when setting the level in our configuration file to our new custom level – “audit”. This actually performed as a filter for that level and only that level in the the output.
This was pretty neat as by default log4j2 doesn’t know anything about our new level when it reads in the configuration file.
<Root level=”audit”>
<AppenderRef ref=”STDOUT” />
<AppenderRef ref=”FILE” />
</Root>
2016-09-02 21:24:23 | AUDIT | utility.CustomVersion (CustomVersion.java:21) - first auditing message
2016-09-02 21:24:23 | AUDIT | utility.CustomVersion (CustomVersion.java:22) - second auditing message
2016-09-02 21:24:23 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '4'
2016-09-02 21:24:23 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '5'
Finally when changing the filter level to all we will see all log output including our two new levels. You can see both AUDIT and the SILLYDEBUG levels as expected.
<Root level=”all”>
<AppenderRef ref=”STDOUT” />
<AppenderRef ref=”FILE” />
</Root>
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:18) - Program starting at
2016-09-02 21:25:09 | TRACE | utility.CustomVersion (CustomVersion.java:19) - add a trace to log output
2016-09-02 21:25:09 | AUDIT | utility.CustomVersion (CustomVersion.java:21) - first auditing message
2016-09-02 21:25:09 | AUDIT | utility.CustomVersion (CustomVersion.java:22) - second auditing message
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square
2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 1
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 1
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:28) - 1 x 1 = 1
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square
2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 2
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 2
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:28) - 2 x 2 = 4
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square
2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 3
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 3
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:28) - 3 x 3 = 9
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square
2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 4
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 4
2016-09-02 21:25:09 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '4'
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:28) - 4 x 4 = 16
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:20) - entering square
2016-09-02 21:25:09 | DEBUG | utility.CustomMathV (CustomMathV.java:21) - parameter is 5
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:23) - mathmatics of squared using 5
2016-09-02 21:25:09 | AUDIT | utility.CustomMathV (CustomMathV.java:30) - extremely large numbers being used in math - value = '5'
2016-09-02 21:25:09 | SILLYDEBUG | utility.CustomMathV (CustomMathV.java:37) - exiting square
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:28) - 5 x 5 = 25
2016-09-02 21:25:09 | DEBUG | utility.CustomVersion (CustomVersion.java:39) - add some additional debug to output
2016-09-02 21:25:09 | INFO | utility.CustomVersion (CustomVersion.java:40) - Program finishing at Other discoveries
One rather interesting thing about these custom levels was how forgiving log4j2 seemed to be of levels that did not exist.
During my testing I accidentally created an unknown level due to a typo only to discover that that message was silently ignored. If I then created the level prior to it being used, the level functioned as exactly as it should. It is not clear if this is a bug or a feature.
I made another interesting discovery while fooling around with Apache Ant. It was surprising not to see the file and line number in my log output. It took a few minutes of head scratching to realize that the program was not compiled with debugging on.
DEBUG | 2016-08-30 23:08:56 | [main] de.companyname.helloworld.HelloWorld (null:-1) - HelloWorld starting
INFO | 2016-08-30 23:08:56 | [main] de.companyname.helloworld.HelloWorld (null:-1) - Hello World!
DEBUG | 2016-08-30 23:08:56 | [main] de.companyname.helloworld.HelloWorld (null:-1) - HelloWorld finishing
The solution was easy enough. Simply change the ant script to turn on debugging while compiling and recompile the program.
Test program
CustomProgram.java
package de.companyname.utility;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class CustomVersion {
static Level AUDIT = Level.forName("AUDIT",350);
static Level SPECIAL = Level.forName("SPECIAL", 399);
public static void main(String[] args)
{
Logger logfile = LogManager.getLogger(CustomVersion.class.getName());
logfile.info("Program starting at " + "");
logfile.trace("add a trace to log output");
logfile.log(AUDIT, "first auditing message");
logfile.log(AUDIT, "second auditing message");
for (int index = 1; index <= 5; index++)
{
try {
int square = de.companyname.utility.CustomMathV.square(index);
logfile.info(index + " x " + index + " = " + square);
}
catch (Exception ex)
{
logfile.fatal(" while processing value " + index);
logfile.fatal(ex.getMessage());
}
}
logfile.log(Level.getLevel("UNDEFINED"), "some xxxx message");
logfile.debug("add some additional debug to output");
logfile.info("Program finishing at " + "");
}
}CustomMathV.java
package de.companyname.utility;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class CustomMathV {
/*
* will return the square of the value input.
* this method will only be for the range of positive numbers.
*/
static public int square (int value) throws Exception
{
Level AUDIT = Level.forName("AUDIT", 350);
Level SILLYDEBUG = Level.forName("SILLYDEBUG", 9999);
Logger logfile = LogManager.getLogger(CustomMathV.class.getName());
logfile.log(SILLYDEBUG, "entering square");
logfile.debug("parameter is " + value);
logfile.log(SILLYDEBUG, "mathmatics of squared using " + value);
int retval = 0;
if (value > 0)
{
retval = value * value;
if (value >= 4)
logfile.log(AUDIT,"extremely large numbers being used in math - value = '" + value + "'");
}
else
{
logfile.debug("invalid value of " + value + " given");
}
logfile.log(SILLYDEBUG, "exiting square");
return retval;
}
}log4j2-custom.xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config">
<Properties>
<Property name="LOG_NAME">logfile.log</Property>
<Property name="FILEPATTERN">%-5p | %d{yyyy-MM-dd HH:mm:ss} | [%t] %C (%F:%L) - %m%n</Property>
<Property name="PATTERN">%d{yyyy-MM-dd HH:mm:ss} | %-5p | %C{2} (%F:%L) - %m%n</Property>
</Properties>
<Appenders>
<File name="FILE" fileName="${LOG_NAME}" append="true">
<PatternLayout pattern="${FILEPATTERN}"/>
</File>
<Console name="STDOUT" target="SYSTEM_OUT">
<PatternLayout pattern="${PATTERN}"/>
</Console>
</Appenders>
<Loggers>
<!-- add this line to get debug output for this particular class -->
<Logger name="dex.companyname.utility.Mymath" level="debug"/>
<Logger name="dex.companyname.utility.CustomMath" level="debug"/>
<Root level="info">
<AppenderRef ref="STDOUT" />
<AppenderRef ref="FILE" />
</Root>
</Loggers>
</Configuration>
runProgram.sh
#!/bin/bash
VMARGS="-Dlog4j.configurationFile=resources/log4j2-custom.xml "
CP=/tmp/version3/lib/log4j-api-2.6.2.jar:/tmp/version3/lib/log4j-core-2.6.2.jar:.
PGM=de.companyname.utility.CustomVersion
CMD="java -cp $CP $VMARGS $PGM"
echo $CMD
$CMD
References
http://logging.apache.org/log4j/2.x/manual/customloglevels.html
Note: The example was compiled with java 1.8 and uses log4j-api-2.6.2.jar and log4j-core-2.6.2.jar
