Logging in NetBeans

The logging system in NetBeans is based on the standard JDK's java.util.logging and complies to it as much as possible. This document sumarizes the basic usecases and shall be treated as a guide for writing good NetBeans ready logging code. The info given here is valid for default configuration of the logger as it is used in NetBeans. However it is possible to fully replace the system by providing own logging properties as in any other JDK application. Then of course the behaviour may get completely different.

Rather than printing raw exceptions to the console or implementing custom debug or logging facililities, code may use the Logger to access logging in a higher-level fashion. This way the logging messages can be dynamically turned on and off by single switch on command line or even during runtime.

Another important thing is to chain stack traces to exceptions using Throwable.initCause(Throwable), permitting you to throw an exception of a type permitted by your API signature while safely encapsulating the root cause of the problem (in terms of other nested exceptions). Code should use Logger.log(Level.SEVERE, msg, exception) rather than directly printing caught exceptions, to make sure nested annotations are not lost and to allow pluged in handlers of logging to process the exceptions.

It is possible to use global logger but it is preferred to create named and shared instances of loggers. The later has the advantage of finer control of what is going to be logged or not, as each named instance can be turned on/off individually by using a command line property.

Turning Logging On and Off

As the logging system is completely JDK based, one can use the traditional properties of LogManager and customize logging completely by themselves.

However there is a simpler way how to enable logging of an named logger. Just start NetBeans with -J-Dname.of.the.Logger.level=100 or any other number and all the log Levels with higher or equal value will immediatelly be enabled and handled by the system.

It is possible to turn the logging dynamically when the application is running. It is enough to just:

System.setProperty("name.of.the.Logger.level", "100");
LogManager.getLogManager().readConfiguration();

Of course this only works if the default NetBeans logger is in place. Sometimes however it may make sence to provide completely different logger. This can be done by one of two JDK standard properties: java.util.logging.config.file or java.util.logging.config.class as described at LogManager's javadoc. If these properties are provide during the startup of the system, then the logging is fully dedicated to the configured custom loggers and of course no NetBeans standard configuration properties work.

How to Write Logging Friendly Code

Handling Exceptions

To handle an exception and sent it to the log file (and possibly show blinking icon to the user in bottom right corner of main window):

private static final Logger logger = Logger.getLogger(ThisClass.class.getName());
try {
    foo.doSomething();
} catch (IOException ioe) {
    logger.log(Level.SEVERE, null, ioe);
}

WARNING behaves the same way by default.

If the exception is not important, and by default shall not be shown or logged at all one can use the Level.FINE, Level.FINER or Level.FINEST:

try {
    foo.doSomething();
} catch (IOException ioe) {
    logger.log(Level.FINE, "msg", ioe);
}

The easiest way to make sure an exception is reported to the user is to use the dialog API with a code like this:

try {
  // some operations
} catch (Exception ex) {
  NotifyDescriptor.Exception e = new NotifyDescriptor.Exception(ex);
  DialogDisplayer.getDefault().notifyLater(e);
}

This code will present a dialog box with warning message extracted from the exception ex sometime in the future - e.g. when the AWT event queue is empty and can show the dialog. Use of notifyLater to plain notify is recommended in order to prevent deadlocks and starvations

Retain nested stacktraces / change exception type

To rethrow an exception use standard JDK's Throwable.initCause(Throwable) method. It is going to be properly annotated and printed when sent to logger:

public void doSomething() throws IOException {
    try {
        doSomethingElse();
    } catch (IllegalArgumentException iae) {
        IOException ioe = new IOException("did not work: " + iae);
        ioe.initCause(iae);
        throw ioe;
    }
}
// ...
try {
    foo.doSomething();
} catch (IOException ioe) {
    logger.log(Level.WARNING, null, ioe);
}

Logging a warning and debug messages

Logging shall usually be done with a named loggers, as that allows proper turning on and off from the command line. To log something into the log file one should use Level.INFO or higher:

private static final Logger LOG =
    Logger.getLogger("org.netbeans.modules.foo");
public void doSomething(String arg) {
    if (arg.length() == 0) {
        LOG.warning("doSomething called on empty string");
        return;
    }
    // ...
}

For writing debugging messages it is also better to have a named logger, but the important difference is to use Level.FINE and lower severity levels:

package org.netbeans.modules.foo;
class FooModule {
    public static final Logger LOG =
        Logger.getLogger("org.netbeans.modules.foo");
}
// ...
class Something {
    public void doSomething(String arg) {
        FooModule.LOG.log(Level.FINER, "Called doSomething with arg {0}", arg);
    }
}

Annotate Exceptions

There is an easy way how to annotate exceptions with localized and non-localized messages in NetBeans. One can use Exceptions.attachMessage or Exceptions.attachLocalizedMessage . The non-localized messages are guaranteed to be printed when one does ex.printStackTrace(), to extract associated localized message one can use Exceptions.findLocalizedMessage .

In spite of what one might think the JDK logging API is not just about sending textual messages to log files, but it can also be used as a communication channel between two pieces of the application that need to exchange structured data. What is even more interesting is that this kind of extended usage can coexist very well with the plain old good writing of messages to log files. This is all possible due to a very nice design of the single logging record - the LogRecord.

Well written structured logging shall use the localized message approach and thus assign to all its LogRecords a ResourceBundle and use just a key to the bundle as the actually logged message. This is a good idea anyway, as it speeds up logging, because if the message is not going to be needed, the final string is not concatenated at all. However this would not be very powerful logging, so another important thing is to provide parameters to the LogRecord via its setParameters method. This, in combination with the MessageFormat used when the final logger is composing the logged message, further delay's the concatenations of strings. Morevoer it allows the advanced communication described above - e.g. there can be another module consumming the message which can directly get access to live objects and processes them in any way.

Here is an example of the program that uses such structured logging:

public static void main(String[] args) {
    ResourceBundle rb = ResourceBundle.getBundle("your.package.Log");
    int sum = 0;
    for (int i = 0; i < 10; i++) {        
        LogRecord r = new LogRecord(Level.INFO, "MSG_Add");
        r.setResourceBundle(rb);
        r.setParameters(new Object[] { sum, i });
        Logger.global.log(r);
        sum += i;
    }        
    LogRecord r = new LogRecord(Level.INFO, "MSG_Result");
    r.setResourceBundle(rb);
    r.setParameters(new Object[] { sum });
    Logger.global.log(r);
}    

Of course the two keys has to be reasonably defined in the Log.properties bundle:

# {0} - current sum
# {1} - add
MSG_Add=Going to add {1} to {0}
# {0} - final sum
MSG_Result=The sum is {0}

When executed with logging on, this example is going to print the expected output with the right messages and well substituted values:

INFO: Going to add 0 to 0
INFO: Going to add 1 to 0
INFO: Going to add 2 to 1
INFO: Going to add 3 to 3
INFO: Going to add 4 to 6
INFO: Going to add 5 to 10
INFO: Going to add 6 to 15
INFO: Going to add 7 to 21
INFO: Going to add 8 to 28
INFO: Going to add 9 to 36
INFO: The sum is 45    

This not surprising behaviour, still however it is one of the most efficient because the text Going to add X to Y is not constructed by the code itself, but by the logger, and only if really needed. So the descrbied logging style is useful of its own, however the interesting part is that one can now write following code and intercept behaviour of one independent part of code from another one:

public class Test extends Handler {
    private int add;
    private int sum;
    private int allAdd;
    public void publish(LogRecord record) {
        if ("MSG_Add".equals(record.getMessage())) {
            add++;
            allAdd += ((Integer)record.getParameters()[1]).intValue();
        }
        if ("MSG_Result".equals(record.getMessage())) {
            sum++;
        }
    }
    public void flush() {
        Logger.global.info("There was " + add + " of adds and " + sum + " of sum outputs, all adding: " + allAdd);
    }
    public void close() { flush(); }       
    static {
        Logger.global.addHandler(new Test());
    }
}   

The basic trick is to register own Handler and thus get access to provided LogRecords and process them in any custom way, possibly pretty different than just printing the strings to log files. Of course, this is only possible because the handler understand the generic names of logged messages - e.g. MSG_Add and MSG_Result and knows the format of their arguments, it can do the analysis, and output:

INFO: There was 10 of adds and 1 of sum outputs, all adding: 45

Indeed a structural logging can achive much more than shown in this simplistic example. Moreover it seems to be one of the most effective ways for logging, so it is highly recommended to use it where possible.