Custom logging for SFS2X Extensions

In this recipe we will take a look at how we can tweak the logging configuration in SmartFoxServer 2X in order to do advanced logging from Extension code.

The standard SFS2X Extension API already provide a straightforward way of logging any data to the standard log files via the trace() command.

trace("Hello from my Extension");

The result is this:

09:16:16,584 INFO  [main] Extensions     - {MyExt}: Hello from my Extension

which can be broken down to:

  • 09:16:16,584 (time)
  • INFO (log level)
  • [main] (name of running thread)
  • Extensions (logging category)
  • {MyExt}
  • Hello from my Extension (the actual log message)

In this recipe we’re going to customize the logging for our Extension by changing its format and isolating our logs in separate files. This way we’ll be able to investigate our game’s log without all the other messages generated by SmartFoxServer.

» Setting up Log4J

Log4J is a very popular logging library that has been around for over a decade and it is used by SmartFoxServer via an abstraction layer called SLF4J.

We can open its configuration file, located under {SFS2X}/config/log4j.properties, with any text editor and add this block:

# MyExt FileAppender
log4j.appender.myExtAppender=org.apache.log4j.DailyRollingFileAppender
log4j.appender.myExtAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.myExtAppender.File=logs/myExt/myExt.log
log4j.appender.myExtAppender.layout.ConversionPattern=%d{dd MMM yyyy | HH:mm:ss,SSS} | %-5p | %t | %c{3} | %3x | %m%n
log4j.appender.myExtAppender.Encoding=UTF-8
log4j.appender.myExtAppender.DatePattern='.'yyyy-MM-dd
log4j.category.my.extension=INFO,myExtAppender

This section can be added right at the top of the file, below the initial comment lines which are denoted by a # (hashtag) sign.

The log4j.appender.<some-name> declaration allows to define a custom appender (myExtAppender) which is configured to use the DailyRollingFileAppender class from Log4J. This class rolls logs files on a daily basis, appending the current date to the tail of the log file name.

myExtAppender.File configures the position and file name of our custom log files relative to the SmartFoxServer’s root folder.

myExtAppender.layout.ConversionPattern declares the format of each logging line. This contains quite a lot of tokens that are useful to control which data and format we want to use when logging. You can learn all the details about pattern formats by consulting the official documentation.

 myExtAppender.DatePattern defines the date pattern discussed in the first section

Finally log4j.category.my.extension declares a new Log4J category and sets its output to both the default consoleAppender and our custom myExtAppender.

A category in Log4J represents a package name, indicating that all classes having the same pattern in their package name will send their logs to the defined appenders. In other words this means that all classes under my.extension.* package will send their log messages to myExtAppender.

» Using Log4J from Extension code

Now it is time to write some Extension code and see how we can use our newly customized logger.

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

...
...

public class MyGameExtension extends SFSExtension
{
	private final Logger log = LoggerFactory.getLogger(MyGameExtension.class);

	public void init()
	{
		if (log.isDebugEnabled())
			log.debug("This message will show only if in DEBUG mode.")

		log.info("This is a regular INFO message");

		log.warn("This is a WARN message, notifying an exception");

		log.error("Bad news, an unrecoverable error just happened");
	}
}

The code imports two classes from the SLF4J package, this is because we never work with our logging classes directly. Instead we use an abstraction which in turn allows to swap a number of logging implementations at runtime.

Setting this aside, we obtain the log object via the LoggerFactory class and we can test it by logging different messages using different log levels.

Notice how we check for isDebugEnabled() before using the debug level, this is pretty important if you have lots of debugging messages in your Extension code. Debug level is recommended for development and testing and should be turned off in production.

In the previous configuration snippet we have this line:

log4j.category.my.extension=INFO,consoleAppender,myExtAppender

where INFO can be replaced with DEBUG, WARN or ERROR, each defining the lowest level that allowed to generate output in the log files.