Maintenance Logging

[Immortius]

Name: Logging
Summary: Anything related to logging - framework, guidelines, hints
Scope: Engine
Current Goal: Maintenance
Phase: Maintenance
Curator: Immortius
Related:

I've just done review of the logging in Terasology, and made the following changes:

• Switched from using Java logging directly, to using slf4j (Simply Logging Framework for Java). This has a nicer API, and allows us to switch to a different logging implementation easily if desired.
• Checked and changed the log level of the log statements. Many things have be switched from info to debug level, to reduce log spam.
• Fixed a number of error log statements that weren't including the exception causing them

So the new system uses the following format for creating a logger:

private static final Logger logger = LoggerFactory.getLogger(TerasologyEngine.class);

For IntelliJ users I suggest setting up a live template that looks like this

private static final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger($CLASS$.class);

Then you can insert the line with ctrl+j, and it will automatically use the right class name.

Parameterized logging looks like this:

logger.info("Found a {} under a {} wearing a {}", cat, mat, hat);

All error logging in response to an exception should include the exception as well

logger.error("Error opening file '{}'", filename, exception);

Some general guidelines on the logging levels:

• Error should be used for anything fatal, or anything that needs to be looked at promptly. Broken assets, broken prefabs, unexpected exceptions.
• Warnings are for things that won't hurt, but still need to be looked at. Missing assets, entities using missing components, exceptions that are semi-expected.
• Info is for major lifecycle events and generally useful information to log, opengl capabilities.
• Debug is for logging for development and debugging purposes. It should be focused on lifecycle events once more -not something that happens in inner loops or otherwise extremely frequently.
• Trace is for development and debugging purposes, but at a level that is getting too detailed for general debugging. Trace statements should generally be temporary, and removed once there is no immediate need for them - but using trace level means they will be turned off at least if you forget to remove them.

 

[Cervator]

Cool

Curiously, what's the difference / choice behind slf4j vs log4j? I hadn't heard of the first one before, but then I haven't exactly gone looking.

 

[Immortius]

SLF4J, like Apache Commons Logging, is facades that sits over an actual logging implementation of the developer's choice. So you log through the SLF4J api, and then can have it actually log to Log4j, or Logback, or some other implementation. At the moment I've left it running against Java Logging, but we can trivially switch implementation now (to Log4j, for instance).

SLF4J also gives us some flexibility when dealing with libraries using different logging mechanisms - it can capture their logs and redirect them back to the desired mechanism.

As for Apache Commons Logging vs SLF4J, from my (rather limited) experience with SLF4J, it seems much easier to configure - you include the SLF4J-api library at compile time, and then an SLF4J implementation library at runtime.

 

[Cervator]

Ahh - alright

 

[Skaldarnar]

Heya, nice logging system, Immortius !
How exactly do I use the debug logging level? Do I have to change any property file or something?

 

[Immortius]

My understanding is Java Logging has support for a logging properties file of some sort, I haven't gotten around to trying it yet.

It can also be set programmatically.

 

[Immortius]

A small update - in the multiplayer branch I've switched the logging framework to Logback - this has two advantages:

1. Logging can now be controlled through a config file. Logback supports a groovy config file or an xml one. For general usage I've chosen the groovy format - this has the advantage of allow it to get the log location from the PathManager at runtime. Unfortunately it doesn't work when running through IntelliJ as IntelliJ compiles the groovy file - Logback expects the uncompiled groovy file. Possibly can be fixed but needs research, so in the meantime I've included the xml config file as a fallback (is only used if the groovy file cannot be found)

2. We no longer need much programmatic logging configuration, except for a small bit to map System.out and System.err to slf4j when running lwjgl in debug mode (as it just logs to those streams)

 

[Cervator]

Bump. Was wondering how we'd guide end-users to most easily change the logging level when testing the game from a binary and figured we had a thread on it. Moved it to the "new" Core Projects forum

I haven't spent the time yet to figure out how we'd change it via command line. A quick Google search suggested Logback favors a configuration file over command line parameters, but we don't have one outside the jars with the zip version of the game. Copying one to the root of the install dir then launching the game with:

java -Dlogback.configurationFile=logback.groovy -jar Terasology.jar -homedir

Didn't seem to change anything though (having changed to debug inside the logback.groovy file). Unsure if I didn't tweak the config file right, refer to it right, or if we need to tweak something to accept changes at runtime via binary. Anybody know?

 

[msteiger]

You can activate some debug output by using a static logger class in the main method. You can even access the logback configurator (JoranConfigurator) if logback is on "compile" dependency (not compileTest).

That said, this issue should have been fixed by now (afaik the resources source set was not included correctly in the gradle script). Is that a recent issue?