« Back to home

SLF4J and XPages Java debugging

I like to write code once and be able to run it both in the Domino XPages environment, and in regular Java environments. That means I don’t want to use any Domino-specific logging.

I also like the SLF4J interface, at least on the Java source code side of things. In particular, I like how easy it is to log values using parameterized logging:

// Painful JDK logging
Logger logger = Logger.getLogger(MyClass.class.getName());
logger.log(Level.DEBUG, "Coords = " + Integer.toString(x) +
  "," + Integer.toString(y));

// Fast and easy SLF4J logging
Logger logger = LoggerFactory.getLogger(MyClass.class);
logger.debug("Coords = {},{}", x, y);

If SLF4J doesn’t need to output the message because of the logging level, it doesn’t bother to compute the necessary string values. But the biggest advantage of all is that I can plug in whatever logging system I want underneath — Log4j, Jakarta Commons Logging, Logback (when I’m running code on the command line), simple files, or (as in this case) Java’s standard logging facilities.

Getting SLF4J logging statements to work in XPages is pretty simple. You need slf4j-api-*.jar and slf4j-jdk14-*.jar; the former provides the SLF4J API, the latter glues it to the traditional Java runtime logging that XPages and Domino use. Since I run the servers I use, I’ve got them all set up with the relevant jar files server side. If you don’t have that luxury, you can always bundle the jar files in your apps.

(Since the XPages Extension Library uses SLF4J, it might be possible to use whatever version it bundles, but I’m not completely sure and haven’t tried it.)

So, now I can write SLF4J log statements in my code. I try it, and notice that only INFO and higher log statements actually get recorded anywhere. Anything at DEBUG or TRACE level is apparently ignored, even though XPages has a trace logging file set up in ~domino/domino/workspace/logs/trace-log-0.xml. What gives?

This brings me to one thing I don’t like about either SLF4J or JDK logging: The apparent painfulness of changing logging levels at run time. Both logging systems are typically configured using Java properties files or arguments given to the JVM at start. But let’s investigate what’s actually going on. I added the following to Java code called by an XPage:

java.util.logging.Logger rootlogger = java.util.logging.Logger.getLogger("");
for (java.util.logging.Handler h : rootlogger.getHandlers()) {
  System.out.println("Handler " + h.getClass().getSimpleName() + " " + h.getLevel().toString());
}

The code gets the root logger, then loops through the handlers which actually handle the output. In the console log I see this:

Jan  6 16:15:14 tecdev domino[1332]: HTTP JVM: Handler DominoConsoleHandler INFO 
Jan  6 16:15:14 tecdev domino[1332]: HTTP JVM: Handler RCPXMLLogHandler INFO
Jan  6 16:15:14 tecdev domino[1332]: HTTP JVM: Handler RCPXMLTraceHandler FINEST

So the handlers are set up as you might expect: INFO level and above goes to console and regular log, everything goes to trace log. So why didn’t I see my debug logs?

The answer is that Domino configures .level = WARNING for the root logger, so nothing below WARNING level ever gets to the handlers. The [XPages Portable Command Guide]() will tell you that the file in question is ~domino/domino/workspace/.config/rcpinstall.properties, and will tell you how to override the settings using a bootstrap.properties or log.properties file… but that’s a lot of work and requires server-side changes.

There has to be an easier way, right? And there is. The key is understanding that Java logging arranges logging preferences in a hierarchy based on the package name you use for the getLogger call. In my case, all my code is under a particular package name. So I can create a logger at package level, set its level to DEBUG, and add my own FileHandler:

Logger mine = Logger.getLogger("com.ath0");
mine.setLevel(Level.FINE);
try {
  mine.addHandler(new java.util.logging.FileHandler("%t/my.log", true));
} catch (IOException e) {
  System.err.println("Cannot create debug log file my.log in temporary directory");
}

Add that to my code, and suddenly all the debug messages from my SLF4J logging calls flow to the trace log as one might hope — and they also flow to the temporary log file on the server for easy debugging. (The %t gets replaced with the temporary directory path.) Because I set the override for my package name, I don’t get my logs filled with internal XPages debugging information. Best of all, the main Domino server console doesn’t get filled with debug messages.

Yes, I’m having to mess with Java’s native logging, but that’s only 7 lines of XPages-specific code. All the actual logging can be done using standard SLF4J calls, which means I can use exactly the same code everywhere.

The advantage of setting debug levels in code, rather than in server config files, is that I can now implement a way to temporarily turn on debug logging on the production server, without needing to alter its config. For instance, I could make my XPage turn on debugging if the parameter &debug is added to the URL, or if the current username is me, or if an application-level debug flag is set by checking a box on a configuration interface.

Incidentally, if you happen to be writing command line applications and need to change the console logging level for SLF4J and Logback, the incantation looks like this:

((ch.qos.logback.classic.Logger)
  LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME))
  .setLevel(ch.qos.logback.classic.Level.DEBUG);

I use docopt for Java to provide the command line parsing for my Java console programs, and add a --debug option which switches the log level at run time using the above code.