org.openide.util.base.doc-files.logging.html Maven / Gradle / Ivy
Logging in NetBeans
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();
and logging state for the name.of.the.Logger
is changed. The
first line in the above code snippet changes the global properties and
the second one asks the system to refresh the configuration of all
loggers in the system.
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
.
Using Structured Logging for Communication
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.