Better ways of logging Exceptions in SFS2X

A recent discussion on our support forum brought up the struggle of sending enough details to the log files when an Exception is caught on the server side. In this article we provide a few options to improve error reporting in your Extensions and avoid those puzzling, single-line errors.

» The problem

Let’s consider this example:

try
{
	CreateRoomSettings crs = new CreateRoomSettings();
	crs.setName("The Lobby");
	crs.setGame(false);
	crs.setMaxUsers(60);
	
	getApi().createRoom(getParentZone(), crs, null);
}
catch(SFSCreateRoomException ex)
{
	trace("Room creation failure: " + ex);
}

If an error occurs in the API call, this is what we will get in the log files:

10:14:15,712 INFO  [main] Extensions     - {javaTest}: Room creation failure: com.smartfoxserver.v2.exceptions.SFSCreateRoomException: Room creation error. A room with the same name already exists: The Lobby, { Zone: BasicExamples }, null

^{(scroll horizontally to read the full error message)}

While the description is clear and tells you exactly what problem has occurred we have no stack trace to understand where exactly in our code this happened. If this operation is wrapped in a method called by multiple classes it will be pretty difficult to understand where this exception is generated.

In these cases having a full stack trace would help substantially, so let’s see how we can improve our error reporting accordingly.

1) Using the inherited logger

The SFSExtension base class provides access to the underlying logging system via the getLogger() method. With one line of code we can immediately add a stack trace to our error reporting:

try
{
	// Potentially "dangerous" code
}
catch(Exception ex)
{
	getLogger().warn("My custom message", ex);
}

This in turn will generate an output like this in the log files:

10:45:47,965 WARN  [Thread-3] Extensions     - Room creation error
com.smartfoxserver.v2.exceptions.SFSCreateRoomException: Room creation error. A room with the same name already exists: The Lobby, { Zone: BasicExamples }, null
	at com.smartfoxserver.v2.api.SFSApi.createRoom(SFSApi.java:776)
	at sfs2x.extension.logging.CustomLoggerExtension.init(CustomLoggerExtension.java:24)
	at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.createExtension(SFSExtensionManager.java:303)
	at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.reloadExtension(SFSExtensionManager.java:533)
	at com.smartfoxserver.v2.entities.managers.SFSExtensionManager$ExtensionFileChangeListener.fileChanged(SFSExtensionManager.java:111)
	at org.apache.commons.vfs.events.ChangedEvent.notify(ChangedEvent.java:34)
	at org.apache.commons.vfs.provider.AbstractFileSystem.fireEvent(AbstractFileSystem.java:519)
	at org.apache.commons.vfs.provider.AbstractFileSystem.fireFileChanged(AbstractFileSystem.java:487)
	at org.apache.commons.vfs.impl.DefaultFileMonitor$FileMonitorAgent.check(DefaultFileMonitor.java:647)
	at org.apache.commons.vfs.impl.DefaultFileMonitor$FileMonitorAgent.access$200(DefaultFileMonitor.java:418)
	at org.apache.commons.vfs.impl.DefaultFileMonitor.run(DefaultFileMonitor.java:373)
	at java.lang.Thread.run(Thread.java:745)

2) ExceptionMessageComposer

If you want an even more flexible and fine grained system, SFS2X provides a custom helper class called ExceptionMessageComposer, which can be imported from com.smartfoxserver.v2.exceptions

The class adds the ability to attach multiple lines of info to every reported error and provide a better description of the issue in a readable format.

Let’s take a look at an example:

try
{
   // some code
}
catch(IllegalStateException ex)
{
	ExceptionMessageComposer emc = new ExceptionMessageComposer(ex);
	emc.setDescription("Unexpected error during game turn");
	emc.addInfo("Player 1 State: " + player1.getState());
	emc.addInfo("Player 2 State: " + player2.getState());
	emc.addInfo("Last P1 position: " + player1.getPosition());
	emc.addInfo("Last P2 position: " + player2.getPosition());
	emc.addInto("Pieces on board: " + board.countPieces());

	  // ...
  
	log.warn(emc.toString());
}

setDescription() allows us to provide the main description of the error
addInfo() allows to add optional lines of info providing context to the error

In this case we’re adding game state information to the error report so that we can better understand what might have happened. Below is the formatted error found in the logs:

11:09:34,075 WARN  [Thread-3] logging.CustomLoggerExtension     - java.lang.IllegalStateException:
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
Exception: java.lang.IllegalStateException
Message: Invalid move from Player2
Description: Inconsistent state during game turn
Player 1 State: Waiting
Player 2 State: Playing
Last P1 position: G4
Last P2 position: H9
Pieces on board: 15
+--- --- ---+
Stack Trace:
+--- --- ---+
sfs2x.extension.logging.CustomLoggerExtension.init(CustomLoggerExtension.java:25)
com.smartfoxserver.v2.entities.managers.SFSExtensionManager.createExtension(SFSExtensionManager.java:303)
com.smartfoxserver.v2.entities.managers.SFSExtensionManager.reloadExtension(SFSExtensionManager.java:533)
com.smartfoxserver.v2.entities.managers.SFSExtensionManager$ExtensionFileChangeListener.fileChanged(SFSExtensionManager.java:111)
org.apache.commons.vfs.events.ChangedEvent.notify(ChangedEvent.java:34)
org.apache.commons.vfs.provider.AbstractFileSystem.fireEvent(AbstractFileSystem.java:519)
org.apache.commons.vfs.provider.AbstractFileSystem.fireFileChanged(AbstractFileSystem.java:487)
org.apache.commons.vfs.impl.DefaultFileMonitor$FileMonitorAgent.check(DefaultFileMonitor.java:647)
org.apache.commons.vfs.impl.DefaultFileMonitor$FileMonitorAgent.access$200(DefaultFileMonitor.java:418)
org.apache.commons.vfs.impl.DefaultFileMonitor.run(DefaultFileMonitor.java:373)
java.lang.Thread.run(Thread.java:745)
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Performance and optimization

One side effect of using more detailed error reporting is that your log files will blow up in size very quickly, especially on a live server with high traffic. This in turn can hinder performance and fill your hard drive very quickly.

The foremost common sense suggestion is to attach a full stack trace only where needed and avoid to do it everywhere. In general errors that are bound to happen in a single specific spot don’t need the stack trace, as you will know exactly where they happened and why.
On the other hand unexpected/runtime errors will likely be good candidates for extensive reporting.

Logger Configuration
When accessing the inherited logger via getLogger() you can use the DEBUG level to easily switch on/off the detailed logging.
Here’s an example:

try
{
	// Potentially "dangerous" code
}
catch(Exception ex)
{
	if(getLogger().isDebugEnabled()) 
		getLogger().warn("My custom message", ex);
	else
		getLogger().warn("My custom message");
}

Here we generate a detailed report only if the logger is configured in DEBUG mode, otherwise we use the single line, default mode. This strategy can be useful for switching between a test environment and a live setup

ExceptionMessageComposer global settings
When using the ExceptionMessageComposer class we can rely on a couple of global settings in SFS2X, namely:

User friendly exceptions: toggles additional info messages
Use debug mode: toggles the stack trace

Both options are enabled by default and can be modified from the AdminTool’s Server Configurator panel. When both options are turned off you will only get the standard message from the generated Exception.

With this new information under your belt you should now be able to optimize your Extension logging and improve the ability of tracking issues in your code.

SmartFoxServer Blog

News, articles and recipes about SmartFoxServer and multiplayer game development

Better ways of logging Exceptions in SFS2X

» The problem

1) Using the inherited logger

2) ExceptionMessageComposer

Performance and optimization