logging

One of the obstacles to fixing the trunk was the complexity of our logging scheme—in particular, that all processes had to relay their logging output back to the Module Manager to get it written to the log. To remedy this, I’ve converted our old logging scheme to use SLF4J (Simple Logging Facade for Java) and Logback. SLF4J is a popular logging framework which seems to be becomming the standard. Logback is the “native” backend for SLF4J.

Among the advantages of the change are:

  • Logback supports coordinating writes to the same log file from different JVMs, so subprocesses launched by the MM don’t need to send logging information back to it anymore.
  • We can do more detailed logging if we want, since the logging level is configurable.
  • We can delete about 350 LoC from the VASSAL.tools.logging package.

The changes to our code are small. Before we had:

import VASSAL.tools.logging.Logger;

public void doSomething {
  ...
  Logger.log(exception);
}

Now we have:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class SomeClass {
  private static final Logger logger = LoggerFactory.getLogger(SomeClass.class);

  public void doSomething {
    ...
    logger.error("optional message", exception);
  }
}

That’s pretty much all there is to the change, codewise. If you want to log in some class, you need to get a Logger. You can specify the logging level using the five logging methods:

trace()
debug()
info()
warn()
error()

I have the logging level set to log all levels right now, but the default is INFO and higher. Calls to the logger are extremely cheap, so putting in logging at the DEBUG and TRACE levels which we turn off in releases should not cause any performance issues. (Or, an idea I just had: Make the logging level configurable from the preferences, so we could ask users to turn up the logging level in case of problems…)

The only other thing of note is that there’s a configuration file called logback.xml (which is presently under src/) which needs to be on the classpath for logging to work properly. I’ve adjusted the Makefile for that, but probably you guys using Eclipse will need to make some adjustment so that Eclipse can find it.

The documentation for SLF4J is here, but there’s barely anything to it: slf4j.org/

The documentation for Logback is here (logback.qos.ch/) but we’re unlikely to need it, as we never call Logback directly.

One thing I forgot: The log format is a bit more informative now, too:

2010-09-18 15:03:28,485 [0-main] INFO  VASSAL.launch.StartUp - Starting

We have the date, followed by the process ID and thread name in brackets, followed by the log level, the class in which the logging occurred, and finally the message. (This is configurable, so we can change it if we want. The documentation for this is in the Layouts chapter of the Logback documentation, logback.qos.ch/manual/layouts.html.)

This post is old, but it was helpful for me to understand VASSAL v3 version 3.7.9-SNAPSHOT startup and game replay.

I’ve added a few logging trace statements in my local code to some important classes such as Builder and GameState. I can change the log level from INFO to TRACE in logback.xml and get all the verbose trace statements I need. However it would be nice to change the log level at run time without editing configuration.

Has anyone been able to change the log level at run time without editing logback.xml? I tried a few command line options such as -Dlogging.level.VASSAL.build.Builder=TRACE and -Dlogging.level.ch.qos.logback.core.FileAppender=TRACE but had no luck. Perhaps some other VASSAL developer has explored this topic.